[Oct 28 15:46:14] VERBOSE[15358] config.c: == Parsing '/etc/asterisk/logger.conf': [Oct 28 15:46:14] DEBUG[15358] config.c: Parsing /etc/asterisk/logger.conf [Oct 28 15:46:14] VERBOSE[15358] config.c: == Found [Oct 28 15:46:14] VERBOSE[15358] logger.c: Asterisk Queue Logger restarted [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'Command' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'Command' [Oct 28 15:46:20] DEBUG[24973] chan_iax2.c: Not an IPv4 nor IPv6 address, cannot get port. [Oct 28 15:46:20] DEBUG[24973] chan_iax2.c: Not an IPv4 nor IPv6 address, cannot get port. [Oct 28 15:46:20] DEBUG[24973] chan_iax2.c: Not an IPv4 nor IPv6 address, cannot get port. [Oct 28 15:46:20] DEBUG[24973] chan_iax2.c: Not an IPv4 nor IPv6 address, cannot get port. [Oct 28 15:46:20] DEBUG[24973] chan_iax2.c: Not an IPv4 nor IPv6 address, cannot get port. [Oct 28 15:46:20] DEBUG[24973] chan_iax2.c: Not an IPv4 nor IPv6 address, cannot get port. [Oct 28 15:46:20] DEBUG[24973] chan_iax2.c: Not an IPv4 nor IPv6 address, cannot get port. [Oct 28 15:46:20] DEBUG[24973] chan_iax2.c: Not an IPv4 nor IPv6 address, cannot get port. [Oct 28 15:46:20] DEBUG[24973] chan_iax2.c: Not an IPv4 nor IPv6 address, cannot get port. [Oct 28 15:46:20] DEBUG[24973] chan_iax2.c: Not an IPv4 nor IPv6 address, cannot get port. [Oct 28 15:46:20] DEBUG[24973] chan_iax2.c: Not an IPv4 nor IPv6 address, cannot get port. [Oct 28 15:46:20] DEBUG[24973] chan_iax2.c: Not an IPv4 nor IPv6 address, cannot get port. [Oct 28 15:46:20] DEBUG[24973] chan_iax2.c: Not an IPv4 nor IPv6 address, cannot get port. [Oct 28 15:46:20] DEBUG[24973] chan_iax2.c: Not an IPv4 nor IPv6 address, cannot get port. [Oct 28 15:46:20] DEBUG[24973] chan_iax2.c: Not an IPv4 nor IPv6 address, cannot get port. [Oct 28 15:46:20] DEBUG[24973] chan_iax2.c: Not an IPv4 nor IPv6 address, cannot get port. [Oct 28 15:46:20] DEBUG[24973] chan_iax2.c: Not an IPv4 nor IPv6 address, cannot get port. [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'Command' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxStatus' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:20] DEBUG[24973] manager.c: Running action 'MailboxCount' [Oct 28 15:46:30] DEBUG[24946] chan_iax2.c: ip callno count decremented to 0 for 192.168.149.225 [Oct 28 15:46:30] DEBUG[24956] chan_iax2.c: ip callno count incremented to 1 for 192.168.149.225 [Oct 28 15:46:30] DEBUG[24948] chan_iax2.c: schedule decrement of callno used for 192.168.149.225 in 60 seconds [Oct 28 15:46:30] DEBUG[24948] chan_iax2.c: Peer ForPecsAsterisk: got pong, lastms 47, historicms 47, maxms 2000 [Oct 28 15:46:45] DEBUG[24946] chan_iax2.c: ip callno count decremented to 0 for 192.168.159.225 [Oct 28 15:46:45] DEBUG[24950] chan_iax2.c: ip callno count incremented to 1 for 192.168.159.225 [Oct 28 15:46:45] DEBUG[24951] chan_iax2.c: schedule decrement of callno used for 192.168.159.225 in 60 seconds [Oct 28 15:46:45] DEBUG[24951] chan_iax2.c: Peer ForKisvardaAsterisk: got pong, lastms 61, historicms 61, maxms 2000 [Oct 28 15:46:57] DEBUG[24959] chan_sip.c: Allocating new SIP dialog for 73a622934caf08470f9939a8591506c2@172.17.10.200:5060 - OPTIONS (No RTP) [Oct 28 15:46:57] DEBUG[24959] acl.c: For destination '10.101.250.26', our source address is '10.101.10.205'. [Oct 28 15:46:57] DEBUG[24959] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.101.10.205:5060 [Oct 28 15:46:57] DEBUG[24959] chan_sip.c: Initializing initreq for method OPTIONS - callid 101b825555fcf7f83dce57b7069a2ac5@10.101.10.205:5060 [Oct 28 15:46:57] DEBUG[24959] chan_sip.c: Header 0 [ 43]: OPTIONS sip:4113@10.101.250.26:5060 SIP/2.0 [Oct 28 15:46:57] DEBUG[24959] chan_sip.c: Header 1 [ 58]: Via: SIP/2.0/UDP 10.101.10.205:5060;branch=z9hG4bK45354970 [Oct 28 15:46:57] DEBUG[24959] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Oct 28 15:46:57] DEBUG[24959] chan_sip.c: Header 3 [ 58]: From: "Unknown" ;tag=as6584ac98 [Oct 28 15:46:57] DEBUG[24959] chan_sip.c: Header 4 [ 33]: To: [Oct 28 15:46:57] DEBUG[24959] chan_sip.c: Header 5 [ 41]: Contact: [Oct 28 15:46:57] DEBUG[24959] chan_sip.c: Header 6 [ 60]: Call-ID: 101b825555fcf7f83dce57b7069a2ac5@10.101.10.205:5060 [Oct 28 15:46:57] DEBUG[24959] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS [Oct 28 15:46:57] DEBUG[24959] chan_sip.c: Header 8 [ 30]: User-Agent: Asterisk PBX 1.8.0 [Oct 28 15:46:57] DEBUG[24959] chan_sip.c: Header 9 [ 35]: Date: Thu, 28 Oct 2010 13:46:57 GMT [Oct 28 15:46:57] DEBUG[24959] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Oct 28 15:46:57] DEBUG[24959] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Oct 28 15:46:57] VERBOSE[24959] chan_sip.c: Reliably Transmitting (no NAT) to 10.101.250.26:5060: OPTIONS sip:4113@10.101.250.26:5060 SIP/2.0 Via: SIP/2.0/UDP 10.101.10.205:5060;branch=z9hG4bK45354970 Max-Forwards: 70 From: "Unknown" ;tag=as6584ac98 To: Contact: Call-ID: 101b825555fcf7f83dce57b7069a2ac5@10.101.10.205:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.0 Date: Thu, 28 Oct 2010 13:46:57 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Oct 28 15:46:57] DEBUG[24959] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #13956 [Oct 28 15:46:57] DEBUG[24959] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.101.250.26:5060 [Oct 28 15:46:58] DEBUG[24959] chan_sip.c: SIP TIMER: Not rescheduling id #13956:OPTIONS (Method 3) (No timer T1) [Oct 28 15:46:58] VERBOSE[24959] chan_sip.c: Retransmitting #1 (no NAT) to 10.101.250.26:5060: OPTIONS sip:4113@10.101.250.26:5060 SIP/2.0 Via: SIP/2.0/UDP 10.101.10.205:5060;branch=z9hG4bK45354970 Max-Forwards: 70 From: "Unknown" ;tag=as6584ac98 To: Contact: Call-ID: 101b825555fcf7f83dce57b7069a2ac5@10.101.10.205:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.0 Date: Thu, 28 Oct 2010 13:46:57 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Oct 28 15:46:58] DEBUG[24959] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.101.250.26:5060 [Oct 28 15:46:59] DEBUG[24959] chan_sip.c: SIP TIMER: Not rescheduling id #13956:OPTIONS (Method 3) (No timer T1) [Oct 28 15:46:59] VERBOSE[24959] chan_sip.c: Retransmitting #2 (no NAT) to 10.101.250.26:5060: OPTIONS sip:4113@10.101.250.26:5060 SIP/2.0 Via: SIP/2.0/UDP 10.101.10.205:5060;branch=z9hG4bK45354970 Max-Forwards: 70 From: "Unknown" ;tag=as6584ac98 To: Contact: Call-ID: 101b825555fcf7f83dce57b7069a2ac5@10.101.10.205:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.0 Date: Thu, 28 Oct 2010 13:46:57 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Oct 28 15:46:59] DEBUG[24959] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.101.250.26:5060 [Oct 28 15:47:00] DEBUG[24959] chan_sip.c: SIP TIMER: Not rescheduling id #13956:OPTIONS (Method 3) (No timer T1) [Oct 28 15:47:00] VERBOSE[24959] chan_sip.c: Retransmitting #3 (no NAT) to 10.101.250.26:5060: OPTIONS sip:4113@10.101.250.26:5060 SIP/2.0 Via: SIP/2.0/UDP 10.101.10.205:5060;branch=z9hG4bK45354970 Max-Forwards: 70 From: "Unknown" ;tag=as6584ac98 To: Contact: Call-ID: 101b825555fcf7f83dce57b7069a2ac5@10.101.10.205:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.0 Date: Thu, 28 Oct 2010 13:46:57 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Oct 28 15:47:00] DEBUG[24959] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.101.250.26:5060 [Oct 28 15:47:01] DEBUG[24959] chan_sip.c: SIP TIMER: Not rescheduling id #13956:OPTIONS (Method 3) (No timer T1) [Oct 28 15:47:01] VERBOSE[24959] chan_sip.c: Retransmitting #4 (no NAT) to 10.101.250.26:5060: OPTIONS sip:4113@10.101.250.26:5060 SIP/2.0 Via: SIP/2.0/UDP 10.101.10.205:5060;branch=z9hG4bK45354970 Max-Forwards: 70 From: "Unknown" ;tag=as6584ac98 To: Contact: Call-ID: 101b825555fcf7f83dce57b7069a2ac5@10.101.10.205:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.0 Date: Thu, 28 Oct 2010 13:46:57 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Oct 28 15:47:01] DEBUG[24959] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.101.250.26:5060 [Oct 28 15:47:01] NOTICE[24959] chan_sip.c: Peer '4113' is now UNREACHABLE! Last qualify: 7 [Oct 28 15:47:01] DEBUG[24959] chan_sip.c: Destroying SIP dialog 101b825555fcf7f83dce57b7069a2ac5@10.101.10.205:5060 [Oct 28 15:47:01] VERBOSE[24959] chan_sip.c: Really destroying SIP dialog '101b825555fcf7f83dce57b7069a2ac5@10.101.10.205:5060' Method: OPTIONS [Oct 28 15:47:01] DEBUG[24973] manager.c: Examining event: Event: PeerStatus Privilege: system,all ChannelType: SIP Peer: SIP/4113 PeerStatus: Unreachable Time: -1 [Oct 28 15:47:01] DEBUG[24936] devicestate.c: No provider found, checking channel drivers for SIP - 4113 [Oct 28 15:47:01] DEBUG[24936] chan_sip.c: Checking device state for peer 4113 [Oct 28 15:47:01] DEBUG[24936] devicestate.c: Changing state for SIP/4113 - state 5 (Unavailable) [Oct 28 15:47:01] DEBUG[24936] devicestate.c: device 'SIP/4113' state '5' [Oct 28 15:47:01] DEBUG[24970] app_queue.c: Device 'SIP/4113' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue. [Oct 28 15:47:01] DEBUG[24937] app_queue.c: Extension '4113@ext-local' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue. [Oct 28 15:47:02] DEBUG[24973] manager.c: Examining event: Event: ExtensionStatus Privilege: call,all Exten: 4113 Context: ext-local Hint: SIP/4113 Status: 4 [Oct 28 15:47:11] DEBUG[24959] chan_sip.c: Allocating new SIP dialog for 1b60c53d1b3718c3669ca49829b45588@172.17.10.200:5060 - OPTIONS (No RTP) [Oct 28 15:47:11] DEBUG[24959] acl.c: For destination '10.101.250.26', our source address is '10.101.10.205'. [Oct 28 15:47:11] DEBUG[24959] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.101.10.205:5060 [Oct 28 15:47:11] DEBUG[24959] chan_sip.c: Initializing initreq for method OPTIONS - callid 540326b46737eeb143c59fe877688eb9@10.101.10.205:5060 [Oct 28 15:47:11] DEBUG[24959] chan_sip.c: Header 0 [ 43]: OPTIONS sip:4113@10.101.250.26:5060 SIP/2.0 [Oct 28 15:47:11] DEBUG[24959] chan_sip.c: Header 1 [ 58]: Via: SIP/2.0/UDP 10.101.10.205:5060;branch=z9hG4bK7fae4d4c [Oct 28 15:47:11] DEBUG[24959] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Oct 28 15:47:11] DEBUG[24959] chan_sip.c: Header 3 [ 58]: From: "Unknown" ;tag=as1006281a [Oct 28 15:47:11] DEBUG[24959] chan_sip.c: Header 4 [ 33]: To: [Oct 28 15:47:11] DEBUG[24959] chan_sip.c: Header 5 [ 41]: Contact: [Oct 28 15:47:11] DEBUG[24959] chan_sip.c: Header 6 [ 60]: Call-ID: 540326b46737eeb143c59fe877688eb9@10.101.10.205:5060 [Oct 28 15:47:11] DEBUG[24959] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS [Oct 28 15:47:11] DEBUG[24959] chan_sip.c: Header 8 [ 30]: User-Agent: Asterisk PBX 1.8.0 [Oct 28 15:47:11] DEBUG[24959] chan_sip.c: Header 9 [ 35]: Date: Thu, 28 Oct 2010 13:47:11 GMT [Oct 28 15:47:11] DEBUG[24959] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Oct 28 15:47:11] DEBUG[24959] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Oct 28 15:47:11] VERBOSE[24959] chan_sip.c: Reliably Transmitting (no NAT) to 10.101.250.26:5060: OPTIONS sip:4113@10.101.250.26:5060 SIP/2.0 Via: SIP/2.0/UDP 10.101.10.205:5060;branch=z9hG4bK7fae4d4c Max-Forwards: 70 From: "Unknown" ;tag=as1006281a To: Contact: Call-ID: 540326b46737eeb143c59fe877688eb9@10.101.10.205:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.0 Date: Thu, 28 Oct 2010 13:47:11 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Oct 28 15:47:11] DEBUG[24959] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #13959 [Oct 28 15:47:11] DEBUG[24959] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.101.250.26:5060 [Oct 28 15:47:12] DEBUG[24959] chan_sip.c: SIP TIMER: Not rescheduling id #13959:OPTIONS (Method 3) (No timer T1) [Oct 28 15:47:12] VERBOSE[24959] chan_sip.c: Retransmitting #1 (no NAT) to 10.101.250.26:5060: OPTIONS sip:4113@10.101.250.26:5060 SIP/2.0 Via: SIP/2.0/UDP 10.101.10.205:5060;branch=z9hG4bK7fae4d4c Max-Forwards: 70 From: "Unknown" ;tag=as1006281a To: Contact: Call-ID: 540326b46737eeb143c59fe877688eb9@10.101.10.205:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.0 Date: Thu, 28 Oct 2010 13:47:11 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Oct 28 15:47:12] DEBUG[24959] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.101.250.26:5060 [Oct 28 15:47:13] DEBUG[24959] chan_sip.c: SIP TIMER: Not rescheduling id #13959:OPTIONS (Method 3) (No timer T1) [Oct 28 15:47:13] VERBOSE[24959] chan_sip.c: Retransmitting #2 (no NAT) to 10.101.250.26:5060: OPTIONS sip:4113@10.101.250.26:5060 SIP/2.0 Via: SIP/2.0/UDP 10.101.10.205:5060;branch=z9hG4bK7fae4d4c Max-Forwards: 70 From: "Unknown" ;tag=as1006281a To: Contact: Call-ID: 540326b46737eeb143c59fe877688eb9@10.101.10.205:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.0 Date: Thu, 28 Oct 2010 13:47:11 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Oct 28 15:47:13] DEBUG[24959] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.101.250.26:5060 [Oct 28 15:47:14] DEBUG[24959] chan_sip.c: SIP TIMER: Not rescheduling id #13959:OPTIONS (Method 3) (No timer T1) [Oct 28 15:47:14] VERBOSE[24959] chan_sip.c: Retransmitting #3 (no NAT) to 10.101.250.26:5060: OPTIONS sip:4113@10.101.250.26:5060 SIP/2.0 Via: SIP/2.0/UDP 10.101.10.205:5060;branch=z9hG4bK7fae4d4c Max-Forwards: 70 From: "Unknown" ;tag=as1006281a To: Contact: Call-ID: 540326b46737eeb143c59fe877688eb9@10.101.10.205:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.0 Date: Thu, 28 Oct 2010 13:47:11 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Oct 28 15:47:14] DEBUG[24959] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.101.250.26:5060 [Oct 28 15:47:15] DEBUG[24959] chan_sip.c: SIP TIMER: Not rescheduling id #13959:OPTIONS (Method 3) (No timer T1) [Oct 28 15:47:15] VERBOSE[24959] chan_sip.c: Retransmitting #4 (no NAT) to 10.101.250.26:5060: OPTIONS sip:4113@10.101.250.26:5060 SIP/2.0 Via: SIP/2.0/UDP 10.101.10.205:5060;branch=z9hG4bK7fae4d4c Max-Forwards: 70 From: "Unknown" ;tag=as1006281a To: Contact: Call-ID: 540326b46737eeb143c59fe877688eb9@10.101.10.205:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.0 Date: Thu, 28 Oct 2010 13:47:11 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Oct 28 15:47:15] DEBUG[24959] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.101.250.26:5060 [Oct 28 15:47:15] DEBUG[24959] chan_sip.c: Destroying SIP dialog 540326b46737eeb143c59fe877688eb9@10.101.10.205:5060 [Oct 28 15:47:15] VERBOSE[24959] chan_sip.c: Really destroying SIP dialog '540326b46737eeb143c59fe877688eb9@10.101.10.205:5060' Method: OPTIONS [Oct 28 15:47:25] DEBUG[24959] chan_sip.c: Allocating new SIP dialog for 5260d33b66ca03f8296d3be6565d8ae4@172.17.10.200:5060 - OPTIONS (No RTP) [Oct 28 15:47:25] DEBUG[24959] acl.c: For destination '10.101.250.26', our source address is '10.101.10.205'. [Oct 28 15:47:25] DEBUG[24959] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.101.10.205:5060 [Oct 28 15:47:25] DEBUG[24959] chan_sip.c: Initializing initreq for method OPTIONS - callid 6b6385b93cc9a5a516b4a6bb415b0393@10.101.10.205:5060 [Oct 28 15:47:25] DEBUG[24959] chan_sip.c: Header 0 [ 43]: OPTIONS sip:4113@10.101.250.26:5060 SIP/2.0 [Oct 28 15:47:25] DEBUG[24959] chan_sip.c: Header 1 [ 58]: Via: SIP/2.0/UDP 10.101.10.205:5060;branch=z9hG4bK6315e673 [Oct 28 15:47:25] DEBUG[24959] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Oct 28 15:47:25] DEBUG[24959] chan_sip.c: Header 3 [ 58]: From: "Unknown" ;tag=as5f2d2e5c [Oct 28 15:47:25] DEBUG[24959] chan_sip.c: Header 4 [ 33]: To: [Oct 28 15:47:25] DEBUG[24959] chan_sip.c: Header 5 [ 41]: Contact: [Oct 28 15:47:25] DEBUG[24959] chan_sip.c: Header 6 [ 60]: Call-ID: 6b6385b93cc9a5a516b4a6bb415b0393@10.101.10.205:5060 [Oct 28 15:47:25] DEBUG[24959] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS [Oct 28 15:47:25] DEBUG[24959] chan_sip.c: Header 8 [ 30]: User-Agent: Asterisk PBX 1.8.0 [Oct 28 15:47:25] DEBUG[24959] chan_sip.c: Header 9 [ 35]: Date: Thu, 28 Oct 2010 13:47:25 GMT [Oct 28 15:47:25] DEBUG[24959] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Oct 28 15:47:25] DEBUG[24959] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Oct 28 15:47:25] VERBOSE[24959] chan_sip.c: Reliably Transmitting (no NAT) to 10.101.250.26:5060: OPTIONS sip:4113@10.101.250.26:5060 SIP/2.0 Via: SIP/2.0/UDP 10.101.10.205:5060;branch=z9hG4bK6315e673 Max-Forwards: 70 From: "Unknown" ;tag=as5f2d2e5c To: Contact: Call-ID: 6b6385b93cc9a5a516b4a6bb415b0393@10.101.10.205:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.0 Date: Thu, 28 Oct 2010 13:47:25 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Oct 28 15:47:25] DEBUG[24959] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #13962 [Oct 28 15:47:25] DEBUG[24959] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.101.250.26:5060 [Oct 28 15:47:26] DEBUG[24959] chan_sip.c: SIP TIMER: Not rescheduling id #13962:OPTIONS (Method 3) (No timer T1) [Oct 28 15:47:26] VERBOSE[24959] chan_sip.c: Retransmitting #1 (no NAT) to 10.101.250.26:5060: OPTIONS sip:4113@10.101.250.26:5060 SIP/2.0 Via: SIP/2.0/UDP 10.101.10.205:5060;branch=z9hG4bK6315e673 Max-Forwards: 70 From: "Unknown" ;tag=as5f2d2e5c To: Contact: Call-ID: 6b6385b93cc9a5a516b4a6bb415b0393@10.101.10.205:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.0 Date: Thu, 28 Oct 2010 13:47:25 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Oct 28 15:47:26] DEBUG[24959] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.101.250.26:5060 [Oct 28 15:47:27] DEBUG[24959] chan_sip.c: SIP TIMER: Not rescheduling id #13962:OPTIONS (Method 3) (No timer T1) [Oct 28 15:47:27] VERBOSE[24959] chan_sip.c: Retransmitting #2 (no NAT) to 10.101.250.26:5060: OPTIONS sip:4113@10.101.250.26:5060 SIP/2.0 Via: SIP/2.0/UDP 10.101.10.205:5060;branch=z9hG4bK6315e673 Max-Forwards: 70 From: "Unknown" ;tag=as5f2d2e5c To: Contact: Call-ID: 6b6385b93cc9a5a516b4a6bb415b0393@10.101.10.205:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.0 Date: Thu, 28 Oct 2010 13:47:25 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Oct 28 15:47:27] DEBUG[24959] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.101.250.26:5060 [Oct 28 15:47:28] DEBUG[24959] chan_sip.c: SIP TIMER: Not rescheduling id #13962:OPTIONS (Method 3) (No timer T1) [Oct 28 15:47:28] VERBOSE[24959] chan_sip.c: Retransmitting #3 (no NAT) to 10.101.250.26:5060: OPTIONS sip:4113@10.101.250.26:5060 SIP/2.0 Via: SIP/2.0/UDP 10.101.10.205:5060;branch=z9hG4bK6315e673 Max-Forwards: 70 From: "Unknown" ;tag=as5f2d2e5c To: Contact: Call-ID: 6b6385b93cc9a5a516b4a6bb415b0393@10.101.10.205:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.0 Date: Thu, 28 Oct 2010 13:47:25 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Oct 28 15:47:28] DEBUG[24959] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.101.250.26:5060 [Oct 28 15:47:29] DEBUG[24959] chan_sip.c: SIP TIMER: Not rescheduling id #13962:OPTIONS (Method 3) (No timer T1) [Oct 28 15:47:29] VERBOSE[24959] chan_sip.c: Retransmitting #4 (no NAT) to 10.101.250.26:5060: OPTIONS sip:4113@10.101.250.26:5060 SIP/2.0 Via: SIP/2.0/UDP 10.101.10.205:5060;branch=z9hG4bK6315e673 Max-Forwards: 70 From: "Unknown" ;tag=as5f2d2e5c To: Contact: Call-ID: 6b6385b93cc9a5a516b4a6bb415b0393@10.101.10.205:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.0 Date: Thu, 28 Oct 2010 13:47:25 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Oct 28 15:47:29] DEBUG[24959] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.101.250.26:5060 [Oct 28 15:47:29] DEBUG[24959] chan_sip.c: Destroying SIP dialog 6b6385b93cc9a5a516b4a6bb415b0393@10.101.10.205:5060 [Oct 28 15:47:29] VERBOSE[24959] chan_sip.c: Really destroying SIP dialog '6b6385b93cc9a5a516b4a6bb415b0393@10.101.10.205:5060' Method: OPTIONS [Oct 28 15:47:30] DEBUG[24946] chan_iax2.c: ip callno count decremented to 0 for 192.168.149.225 [Oct 28 15:47:30] DEBUG[24953] chan_iax2.c: ip callno count incremented to 1 for 192.168.149.225 [Oct 28 15:47:30] DEBUG[24955] chan_iax2.c: schedule decrement of callno used for 192.168.149.225 in 60 seconds [Oct 28 15:47:30] DEBUG[24955] chan_iax2.c: Peer ForPecsAsterisk: got pong, lastms 47, historicms 47, maxms 2000 [Oct 28 15:47:33] VERBOSE[24959] chan_sip.c: <--- SIP read from UDP:10.16.91.2:5060 ---> INVITE sip:+3696305254@172.17.10.200:5060 SIP/2.0 Via: SIP/2.0/UDP 10.16.91.2:5060;branch=z9hG4bK-d8754z-b5c5c444aee54541-1---d8754z-;rport Max-Forwards: 70 Contact: To: From: ;tag=69d53945703f6225749b640731962a73 Call-ID: 0000115d4cc97f0d7af1eb1df0f0f0f0@10.35.1.1/1 CSeq: 101 INVITE Allow: INVITE, CANCEL, ACK, BYE, REGISTER, OPTIONS, REFER, INFO, UPDATE, PRACK Content-Type: application/sdp Supported: 100rel User-Agent: Deverto Tequet SoftSwitch 6.3.0-pre1-bodnar Privacy: id Remote-Party-ID: ;party=calling;screen=no;privacy=full Content-Length: 281 v=0 o=- 1907627365 1387182515 IN IP4 10.16.91.2 s=- c=IN IP4 10.16.91.2 t=0 0 m=audio 12002 RTP/AVP 18 8 0 101 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendrecv <-------------> [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Header 0 [ 49]: INVITE sip:+3696305254@172.17.10.200:5060 SIP/2.0 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Header 1 [ 89]: Via: SIP/2.0/UDP 10.16.91.2:5060;branch=z9hG4bK-d8754z-b5c5c444aee54541-1---d8754z-;rport [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Header 3 [ 40]: Contact: [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Header 4 [ 32]: To: [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Header 5 [ 76]: From: ;tag=69d53945703f6225749b640731962a73 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Header 6 [ 53]: Call-ID: 0000115d4cc97f0d7af1eb1df0f0f0f0@10.35.1.1/1 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Header 7 [ 16]: CSeq: 101 INVITE [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Header 8 [ 78]: Allow: INVITE, CANCEL, ACK, BYE, REGISTER, OPTIONS, REFER, INFO, UPDATE, PRACK [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Header 9 [ 29]: Content-Type: application/sdp [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Header 10 [ 17]: Supported: 100rel [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Header 11 [ 55]: User-Agent: Deverto Tequet SoftSwitch 6.3.0-pre1-bodnar [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Header 12 [ 11]: Privacy: id [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Header 13 [ 87]: Remote-Party-ID: ;party=calling;screen=no;privacy=full [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Header 14 [ 19]: Content-Length: 281 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Header 15 [ 0]: [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Body 0 [ 3]: v=0 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Body 1 [ 43]: o=- 1907627365 1387182515 IN IP4 10.16.91.2 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Body 2 [ 3]: s=- [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Body 3 [ 19]: c=IN IP4 10.16.91.2 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Body 4 [ 5]: t=0 0 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Body 5 [ 32]: m=audio 12002 RTP/AVP 18 8 0 101 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Body 6 [ 21]: a=rtpmap:18 G729/8000 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Body 7 [ 19]: a=fmtp:18 annexb=no [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Body 8 [ 20]: a=rtpmap:8 PCMA/8000 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Body 9 [ 20]: a=rtpmap:0 PCMU/8000 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Body 10 [ 33]: a=rtpmap:101 telephone-event/8000 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Body 11 [ 15]: a=fmtp:101 0-15 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Body 12 [ 10]: a=ptime:20 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Body 13 [ 10]: a=sendrecv [Oct 28 15:47:33] VERBOSE[24959] chan_sip.c: --- (15 headers 14 lines) --- [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: = Looking for Call ID: 0000115d4cc97f0d7af1eb1df0f0f0f0@10.35.1.1/1 (Checking From) --From tag 69d53945703f6225749b640731962a73 --To-tag [Oct 28 15:47:33] DEBUG[24959] acl.c: For destination '10.16.91.2', our source address is '172.17.10.200'. [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Target address 10.16.91.2:5060 is not local, substituting externaddr [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.244.2:5060 [Oct 28 15:47:33] VERBOSE[24959] netsock.c: == Using UDPTL TOS bits 184 [Oct 28 15:47:33] VERBOSE[24959] netsock.c: == Using UDPTL CoS mark 5 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Setting NAT on UDPTL to On [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Allocating new SIP dialog for 0000115d4cc97f0d7af1eb1df0f0f0f0@10.35.1.1/1 - INVITE (No RTP) [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Oct 28 15:47:33] DEBUG[24959] sip/reqresp_parser.c: Begin: parsing SIP "Supported: 100rel" [Oct 28 15:47:33] DEBUG[24959] sip/reqresp_parser.c: Found SIP option: -100rel- [Oct 28 15:47:33] DEBUG[24959] sip/reqresp_parser.c: Matched SIP option: 100rel [Oct 28 15:47:33] DEBUG[24959] netsock2.c: Splitting '10.16.91.2:5060' gives... [Oct 28 15:47:33] DEBUG[24959] netsock2.c: ...host '10.16.91.2' and port '5060'. [Oct 28 15:47:33] VERBOSE[24959] chan_sip.c: Sending to 10.16.91.2:5060 (NAT) [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Initializing initreq for method INVITE - callid 0000115d4cc97f0d7af1eb1df0f0f0f0@10.35.1.1/1 [Oct 28 15:47:33] VERBOSE[24959] chan_sip.c: Using INVITE request as basis request - 0000115d4cc97f0d7af1eb1df0f0f0f0@10.35.1.1/1 [Oct 28 15:47:33] VERBOSE[24959] chan_sip.c: Found peer 'MTelekomSIP1' for 'anonymous' from 10.16.91.2:5060 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Setting NAT on UDPTL to On [Oct 28 15:47:33] DEBUG[24959] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x1dcc5fe8' [Oct 28 15:47:33] DEBUG[24959] res_rtp_asterisk.c: Allocated port 19458 for RTP instance '0x1dcc5fe8' [Oct 28 15:47:33] DEBUG[24959] rtp_engine.c: RTP instance '0x1dcc5fe8' is setup and ready to go [Oct 28 15:47:33] DEBUG[24959] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x1dcc5fe8' [Oct 28 15:47:33] VERBOSE[24959] netsock2.c: == Using SIP RTP TOS bits 184 [Oct 28 15:47:33] VERBOSE[24959] netsock2.c: == Using SIP RTP CoS mark 5 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Setting NAT on RTP to On [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Setting NAT on UDPTL to On [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Processing session-level SDP o=- 1907627365 1387182515 IN IP4 10.16.91.2... UNSUPPORTED. [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED. [Oct 28 15:47:33] DEBUG[24959] netsock2.c: Splitting '10.16.91.2' gives... [Oct 28 15:47:33] DEBUG[24959] netsock2.c: ...host '10.16.91.2' and port '(null)'. [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Processing session-level SDP c=IN IP4 10.16.91.2... OK. [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Oct 28 15:47:33] VERBOSE[24959] chan_sip.c: Found RTP audio format 18 [Oct 28 15:47:33] DEBUG[24959] rtp_engine.c: Setting payload 18 based on m type on 0x4180bda0 [Oct 28 15:47:33] VERBOSE[24959] chan_sip.c: Found RTP audio format 8 [Oct 28 15:47:33] DEBUG[24959] rtp_engine.c: Setting payload 8 based on m type on 0x4180bda0 [Oct 28 15:47:33] VERBOSE[24959] chan_sip.c: Found RTP audio format 0 [Oct 28 15:47:33] DEBUG[24959] rtp_engine.c: Setting payload 0 based on m type on 0x4180bda0 [Oct 28 15:47:33] VERBOSE[24959] chan_sip.c: Found RTP audio format 101 [Oct 28 15:47:33] DEBUG[24959] rtp_engine.c: Setting payload 101 based on m type on 0x4180bda0 [Oct 28 15:47:33] VERBOSE[24959] chan_sip.c: Found audio description format G729 for ID 18 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Processing media-level (audio) SDP a=fmtp:18 annexb=no... UNSUPPORTED. [Oct 28 15:47:33] VERBOSE[24959] chan_sip.c: Found audio description format PCMA for ID 8 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Oct 28 15:47:33] VERBOSE[24959] chan_sip.c: Found audio description format PCMU for ID 0 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Oct 28 15:47:33] VERBOSE[24959] chan_sip.c: Found audio description format telephone-event for ID 101 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Oct 28 15:47:33] DEBUG[24959] rtp_engine.c: Incorporating payload 0 on 0x4180bda0 [Oct 28 15:47:33] DEBUG[24959] rtp_engine.c: Incorporating payload 8 on 0x4180bda0 [Oct 28 15:47:33] DEBUG[24959] rtp_engine.c: Incorporating payload 18 on 0x4180bda0 [Oct 28 15:47:33] DEBUG[24959] rtp_engine.c: Incorporating payload 101 on 0x4180bda0 [Oct 28 15:47:33] VERBOSE[24959] chan_sip.c: Capabilities: us - 0x108 (alaw|g729), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x108 (alaw|g729) [Oct 28 15:47:33] VERBOSE[24959] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Oct 28 15:47:33] DEBUG[24959] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x1dcc5fe8' [Oct 28 15:47:33] VERBOSE[24959] chan_sip.c: Peer audio RTP is at port 10.16.91.2:12002 [Oct 28 15:47:33] DEBUG[24959] rtp_engine.c: Copying payload 0 from 0x4180bda0 to 0x1dcc61b0 [Oct 28 15:47:33] DEBUG[24959] rtp_engine.c: Copying payload 8 from 0x4180bda0 to 0x1dcc61b0 [Oct 28 15:47:33] DEBUG[24959] rtp_engine.c: Copying payload 18 from 0x4180bda0 to 0x1dcc61b0 [Oct 28 15:47:33] DEBUG[24959] rtp_engine.c: Copying payload 101 from 0x4180bda0 to 0x1dcc61b0 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Peer doesn't provide T.38 UDPTL [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: We're settling with these formats: 0x108 (alaw|g729) [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Checking SIP call limits for device +3696305254 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Updating call counter for incoming call [Oct 28 15:47:33] VERBOSE[24959] chan_sip.c: Looking for +3696305254 in from-trunk-sip-MTelekomSIP1-custom-SIGNAL (domain 172.17.10.200:5060) [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: *** Our native formats are 0x8 (alaw) [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: *** Joint capabilities are 0x108 (alaw|g729) [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: *** Our capabilities are 0x108 (alaw|g729) [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: This channel will not be able to handle video. [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: build_route: Contact hop: [Oct 28 15:47:33] VERBOSE[24959] chan_sip.c: list_route: hop: [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: SIP/MTelekomSIP1-00000010: New call is still down.... Trying... [Oct 28 15:47:33] VERBOSE[24959] chan_sip.c: <--- Transmitting (NAT) to 10.16.91.2:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.16.91.2:5060;branch=z9hG4bK-d8754z-b5c5c444aee54541-1---d8754z-;received=10.16.91.2;rport=5060 From: ;tag=69d53945703f6225749b640731962a73 To: Call-ID: 0000115d4cc97f0d7af1eb1df0f0f0f0@10.35.1.1/1 CSeq: 101 INVITE Server: Asterisk PBX 1.8.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 10.16.91.2:5060 [Oct 28 15:47:33] DEBUG[24936] devicestate.c: No provider found, checking channel drivers for SIP - MTelekomSIP1 [Oct 28 15:47:33] DEBUG[24936] chan_sip.c: Checking device state for peer MTelekomSIP1 [Oct 28 15:47:33] DEBUG[24936] devicestate.c: Changing state for SIP/MTelekomSIP1 - state 1 (Not in use) [Oct 28 15:47:33] DEBUG[24936] devicestate.c: device 'SIP/MTelekomSIP1' state '1' [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newchannel Privilege: call,all Channel: SIP/MTelekomSIP1-00000010 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: anonymous CallerIDName: AccountCode: Exten: +3696305254 Context: from-trunk-sip-MTelekomSIP1-custom-SIGNAL Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: SIPURI Value: sip:anonymous@10.16.91.2:5060 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: SIPDOMAIN Value: 172.17.10.200:5060 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: SIPCALLID Value: 0000115d4cc97f0d7af1eb1df0f0f0f0@10.35.1.1/1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/MTelekomSIP1-00000010 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: anonymous CallerIDName: Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24970] app_queue.c: Device 'SIP/MTelekomSIP1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [+3696305254@from-trunk-sip-MTelekomSIP1-custom-SIGNAL:1] Set("SIP/MTelekomSIP1-00000010", "GROUP()=OUT_8") in new stack [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: from-trunk-sip-MTelekomSIP1-custom-SIGNAL Extension: +3696305254 Priority: 1 Application: Set AppData: GROUP()=OUT_8 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'EXTEN' is '+3696305254' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Goto' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [+3696305254@from-trunk-sip-MTelekomSIP1-custom-SIGNAL:2] Goto("SIP/MTelekomSIP1-00000010", "from-trunk-custom-SIGNAL,+3696305254,1") in new stack [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: from-trunk-sip-MTelekomSIP1-custom-SIGNAL Extension: +3696305254 Priority: 2 Application: Goto AppData: from-trunk-custom-SIGNAL,+3696305254,1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Goto (from-trunk-custom-SIGNAL,+3696305254,1) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'EXTEN' is '+3696305254' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [+3696305254@from-trunk-custom-SIGNAL:1] Set("SIP/MTelekomSIP1-00000010", "__FROM_DID=+3696305254") in new stack [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: from-trunk-custom-SIGNAL Extension: +3696305254 Priority: 1 Application: Set AppData: __FROM_DID=+3696305254 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Gosub' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [+3696305254@from-trunk-custom-SIGNAL:2] Gosub("SIP/MTelekomSIP1-00000010", "app-blacklist-check,s,1") in new stack [Oct 28 15:47:33] DEBUG[15438] app_stack.c: Channel SIP/MTelekomSIP1-00000010 has no datastore, so we're allocating one. [Oct 28 15:47:33] DEBUG[15438] db.c: Unable to find key 'anonymous' in family 'blacklist' [Oct 28 15:47:33] DEBUG[15438] db.c: Unable to find key '' in family 'blacklist' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'GotoIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@app-blacklist-check:1] GotoIf("SIP/MTelekomSIP1-00000010", "0?blacklisted") in new stack [Oct 28 15:47:33] DEBUG[15438] pbx.c: Not taking any branch [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@app-blacklist-check:2] Set("SIP/MTelekomSIP1-00000010", "CALLED_BLACKLIST=1") in new stack [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Return' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@app-blacklist-check:3] Return("SIP/MTelekomSIP1-00000010", "") in new stack [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [+3696305254@from-trunk-custom-SIGNAL:3] Set("SIP/MTelekomSIP1-00000010", "CHANNEL(language)=hu") in new stack [Oct 28 15:47:33] NOTICE[15438] chan_sip.c: Unknown option: 9 [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is '' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '1' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is 'anonymous' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'ExecIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [+3696305254@from-trunk-custom-SIGNAL:4] ExecIf("SIP/MTelekomSIP1-00000010", "1 ?Set(CALLERID(name)=anonymous)") in new stack [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is 'allowed_not_screened' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [+3696305254@from-trunk-custom-SIGNAL:5] Set("SIP/MTelekomSIP1-00000010", "__CALLINGPRES_SV=allowed_not_screened") in new stack [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [+3696305254@from-trunk-custom-SIGNAL:6] Set("SIP/MTelekomSIP1-00000010", "CALLERPRES()=allowed_not_screened") in new stack [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Goto' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [+3696305254@from-trunk-custom-SIGNAL:7] Goto("SIP/MTelekomSIP1-00000010", "from-did-direct,4113,1") in new stack [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Goto (from-did-direct,4113,1) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Macro' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [4113@from-did-direct:1] Macro("SIP/MTelekomSIP1-00000010", "exten-vm,novm,4113") in new stack [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Macro' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-exten-vm:1] Macro("SIP/MTelekomSIP1-00000010", "user-callerid,") in new stack [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'AMPUSER' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '1' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is 'anonymous' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'AMPUSER' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is 'anonymous' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-user-callerid:1] Set("SIP/MTelekomSIP1-00000010", "AMPUSER=anonymous") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'CHANNEL' is 'SIP/MTelekomSIP1-00000010' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'GotoIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-user-callerid:2] GotoIf("SIP/MTelekomSIP1-00000010", "0?report") in new stack [Oct 28 15:47:33] DEBUG[15438] pbx.c: Not taking any branch [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: GotoIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'REALCALLERIDNUM' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '1' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is 'anonymous' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'ExecIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-user-callerid:3] ExecIf("SIP/MTelekomSIP1-00000010", "1?Set(REALCALLERIDNUM=anonymous)") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: ExecIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'REALCALLERIDNUM:1:2' (from 'REALCALLERIDNUM:1:2}" = ""' len 19) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'REALCALLERIDNUM' is 'anonymous' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'CALLERID(number)' (from 'CALLERID(number)})' len 16) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is 'anonymous' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'REALCALLERIDNUM' is 'anonymous' [Oct 28 15:47:33] DEBUG[15438] db.c: Unable to find key 'anonymous/user' in family 'DEVICE' [Oct 28 15:47:33] DEBUG[15438] func_db.c: DB: DEVICE/anonymous/user not found in database. [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is '' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-user-callerid:4] Set("SIP/MTelekomSIP1-00000010", "AMPUSER=") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'AMPUSER' is '' [Oct 28 15:47:33] DEBUG[15438] db.c: Unable to find key '/cidname' in family 'AMPUSER' [Oct 28 15:47:33] DEBUG[15438] func_db.c: DB: AMPUSER//cidname not found in database. [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is '' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-user-callerid:5] Set("SIP/MTelekomSIP1-00000010", "AMPUSERCIDNAME=") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'AMPUSERCIDNAME' is '' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '1' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'GotoIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/MTelekomSIP1-00000010", "1?report") in new stack [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Goto (macro-user-callerid,s,10) [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: GotoIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'ARG1' is '' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'GotoIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-user-callerid:10] GotoIf("SIP/MTelekomSIP1-00000010", "0?continue") in new stack [Oct 28 15:47:33] DEBUG[15438] pbx.c: Not taking any branch [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: GotoIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'TTL' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '1' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'TTL' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '-1' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is '64' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-user-callerid:11] Set("SIP/MTelekomSIP1-00000010", "__TTL=64") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'TTL' is '64' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '1' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'GotoIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-user-callerid:12] GotoIf("SIP/MTelekomSIP1-00000010", "1?continue") in new stack [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Goto (macro-user-callerid,s,19) [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: GotoIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is '"anonymous" ' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'NoOp' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-user-callerid:19] NoOp("SIP/MTelekomSIP1-00000010", "Using CallerID "anonymous" ") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Noop [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Macro [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-exten-vm:2] Set("SIP/MTelekomSIP1-00000010", "RingGroupMethod=none") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'ARG1' is 'novm' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-exten-vm:3] Set("SIP/MTelekomSIP1-00000010", "VMBOX=novm") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'ARG2' is '4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-exten-vm:4] Set("SIP/MTelekomSIP1-00000010", "__EXTTOCALL=4113") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'EXTTOCALL' is '4113' [Oct 28 15:47:33] DEBUG[15438] db.c: Unable to find key '4113' in family 'CFU' [Oct 28 15:47:33] DEBUG[15438] func_db.c: DB: CFU/4113 not found in database. [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is '' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-exten-vm:5] Set("SIP/MTelekomSIP1-00000010", "CFUEXT=") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'EXTTOCALL' is '4113' [Oct 28 15:47:33] DEBUG[15438] db.c: Unable to find key '4113' in family 'CFB' [Oct 28 15:47:33] DEBUG[15438] func_db.c: DB: CFB/4113 not found in database. [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is '' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-exten-vm:6] Set("SIP/MTelekomSIP1-00000010", "CFBEXT=") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'VMBOX' is 'novm' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'CFUEXT' is '' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'RINGTIMER' is '15' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is '""' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-exten-vm:7] Set("SIP/MTelekomSIP1-00000010", "RT=""") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'EXTTOCALL' is '4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Macro' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-exten-vm:8] Macro("SIP/MTelekomSIP1-00000010", "record-enable,4113,IN") in new stack [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'MacroExit' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-record-enable:1] MacroExit("SIP/MTelekomSIP1-00000010", "") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Macro [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'RT' is '""' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DIAL_OPTIONS' is 'tr' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'EXTTOCALL' is '4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Macro' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-exten-vm:9] Macro("SIP/MTelekomSIP1-00000010", "dial-one,"",tr,4113") in new stack [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'ARG3' is '4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-dial-one:1] Set("SIP/MTelekomSIP1-00000010", "DEXTEN=4113") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-dial-one:2] Set("SIP/MTelekomSIP1-00000010", "DIALSTATUS_CW=") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'FROM_DID' is '+3696305254' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'SCREEN' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DEXTEN' is '4113' [Oct 28 15:47:33] DEBUG[15438] db.c: Unable to find key '4113/screen' in family 'AMPUSER' [Oct 28 15:47:33] DEBUG[15438] func_db.c: DB: AMPUSER/4113/screen not found in database. [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is '' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'GosubIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-dial-one:3] GosubIf("SIP/MTelekomSIP1-00000010", "0?screen,1") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: GosubIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'FROM_DID' (from 'FROM_DID}"!="" & "${SCREEN}"="" & "${DB(AMPUSER/${DEXTEN}/screen)}"!=""' len 8) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'FROM_DID' is '+3696305254' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'SCREEN' (from 'SCREEN}"="" & "${DB(AMPUSER/${DEXTEN}/screen)}"!=""' len 6) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'SCREEN' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'DB(AMPUSER/${DEXTEN}/screen)' (from 'DB(AMPUSER/${DEXTEN}/screen)}"!=""' len 28) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'DEXTEN' (from 'DEXTEN}/screen)' len 6) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DEXTEN' is '4113' [Oct 28 15:47:33] DEBUG[15438] db.c: Unable to find key '4113/screen' in family 'AMPUSER' [Oct 28 15:47:33] DEBUG[15438] func_db.c: DB: AMPUSER/4113/screen not found in database. [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is '' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DEXTEN' is '4113' [Oct 28 15:47:33] DEBUG[15438] db.c: Unable to find key '4113' in family 'CF' [Oct 28 15:47:33] DEBUG[15438] func_db.c: DB: CF/4113 not found in database. [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is '' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'GosubIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-dial-one:4] GosubIf("SIP/MTelekomSIP1-00000010", "0?cf,1") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: GosubIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'DB(CF/${DEXTEN})' (from 'DB(CF/${DEXTEN})}"!=""' len 16) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'DEXTEN' (from 'DEXTEN})' len 6) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DEXTEN' is '4113' [Oct 28 15:47:33] DEBUG[15438] db.c: Unable to find key '4113' in family 'CF' [Oct 28 15:47:33] DEBUG[15438] func_db.c: DB: CF/4113 not found in database. [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is '' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DEXTEN' is '4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DEXTEN' is '4113' [Oct 28 15:47:33] DEBUG[15438] db.c: Unable to find key '4113' in family 'DND' [Oct 28 15:47:33] DEBUG[15438] func_db.c: DB: DND/4113 not found in database. [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is '' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '1' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'GotoIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-dial-one:5] GotoIf("SIP/MTelekomSIP1-00000010", "1?skip1") in new stack [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Goto (macro-dial-one,s,8) [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: GotoIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DEXTEN' is '4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'GotoIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-dial-one:8] GotoIf("SIP/MTelekomSIP1-00000010", "0?nodial") in new stack [Oct 28 15:47:33] DEBUG[15438] pbx.c: Not taking any branch [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: GotoIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DEXTEN' is '4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'GotoIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-dial-one:9] GotoIf("SIP/MTelekomSIP1-00000010", "0?continue") in new stack [Oct 28 15:47:33] DEBUG[15438] pbx.c: Not taking any branch [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: GotoIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'CWIGNORE' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DEXTEN' is '4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is 'ENABLED' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is 'ENABLED' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-dial-one:10] Set("SIP/MTelekomSIP1-00000010", "EXTHASCW=ENABLED") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'EXTHASCW' is 'ENABLED' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DEXTEN' is '4113' [Oct 28 15:47:33] DEBUG[15438] db.c: Unable to find key '4113' in family 'CFB' [Oct 28 15:47:33] DEBUG[15438] func_db.c: DB: CFB/4113 not found in database. [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is '' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DEXTEN' is '4113' [Oct 28 15:47:33] DEBUG[15438] db.c: Unable to find key '4113' in family 'CFU' [Oct 28 15:47:33] DEBUG[15438] func_db.c: DB: CFU/4113 not found in database. [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is '' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'GotoIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-dial-one:11] GotoIf("SIP/MTelekomSIP1-00000010", "0?next1:cwinusebusy") in new stack [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Goto (macro-dial-one,s,23) [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: GotoIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'EXTHASCW' is 'ENABLED' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'CWINUSEBUSY' is 'true' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '1' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'GotoIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-dial-one:23] GotoIf("SIP/MTelekomSIP1-00000010", "1?next3:continue") in new stack [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Goto (macro-dial-one,s,24) [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: GotoIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DEXTEN' is '4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is 'UNAVAILABLE' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DEXTEN' is '4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is 'UNAVAILABLE' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DEXTEN' is '4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is 'UNAVAILABLE' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'ExecIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-dial-one:24] ExecIf("SIP/MTelekomSIP1-00000010", "0?Set(DIALSTATUS_CW=BUSY)") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: ExecIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'EXTENSION_STATE(${DEXTEN})' (from 'EXTENSION_STATE(${DEXTEN})}"!="UNAVAILABLE" & "${EXTENSION_STATE(${DEXTEN})}"!="NOT_INUSE" & "${EXTENSION_STATE(${DEXTEN})}"!="UNKNOWN"' len 26) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'DEXTEN' (from 'DEXTEN})' len 6) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DEXTEN' is '4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is 'UNAVAILABLE' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'EXTENSION_STATE(${DEXTEN})' (from 'EXTENSION_STATE(${DEXTEN})}"!="NOT_INUSE" & "${EXTENSION_STATE(${DEXTEN})}"!="UNKNOWN"' len 26) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'DEXTEN' (from 'DEXTEN})' len 6) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DEXTEN' is '4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is 'UNAVAILABLE' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'EXTENSION_STATE(${DEXTEN})' (from 'EXTENSION_STATE(${DEXTEN})}"!="UNKNOWN"' len 26) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'DEXTEN' (from 'DEXTEN})' len 6) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DEXTEN' is '4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is 'UNAVAILABLE' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DEXTEN' is '4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'GotoIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-dial-one:25] GotoIf("SIP/MTelekomSIP1-00000010", "0?nodial") in new stack [Oct 28 15:47:33] DEBUG[15438] pbx.c: Not taking any branch [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: GotoIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DEXTEN' is '4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '1' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'GosubIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-dial-one:26] GosubIf("SIP/MTelekomSIP1-00000010", "1?dstring,1:dlocal,1") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: GosubIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'DEXTEN:-1' (from 'DEXTEN:-1}"!="#"' len 9) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DEXTEN' is '4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '1' [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Incrementing gosub_level [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [dstring@macro-dial-one:1] Set("SIP/MTelekomSIP1-00000010", "DSTRING=") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DEXTEN' is '4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is '4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [dstring@macro-dial-one:2] Set("SIP/MTelekomSIP1-00000010", "DEVICES=4113") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DEVICES' is '4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'ExecIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [dstring@macro-dial-one:3] ExecIf("SIP/MTelekomSIP1-00000010", "0?Return()") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: ExecIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'DEVICES' (from 'DEVICES}"=""' len 7) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DEVICES' is '4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DEVICES' is '4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DEVICES' is '4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'ExecIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [dstring@macro-dial-one:4] ExecIf("SIP/MTelekomSIP1-00000010", "0?Set(DEVICES=113)") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: ExecIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'DEVICES:0:1' (from 'DEVICES:0:1}"="&"' len 11) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DEVICES' is '4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'DEVICES:1' (from 'DEVICES:1})' len 9) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DEVICES' is '4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'DEVICES' (from 'DEVICES}' len 7) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DEVICES' is '4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is '1' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [dstring@macro-dial-one:5] Set("SIP/MTelekomSIP1-00000010", "LOOPCNT=1") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [dstring@macro-dial-one:6] Set("SIP/MTelekomSIP1-00000010", "ITER=1") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'ITER' is '1' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'DEVICES' (from 'DEVICES}' len 7) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DEVICES' is '4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is '4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is 'SIP/4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [dstring@macro-dial-one:7] Set("SIP/MTelekomSIP1-00000010", "THISDIAL=SIP/4113") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'ASTCHANDAHDI' is '1' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '1' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'GosubIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [dstring@macro-dial-one:8] GosubIf("SIP/MTelekomSIP1-00000010", "1?zap2dahdi,1") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: GosubIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'ASTCHANDAHDI' (from 'ASTCHANDAHDI}" != ""' len 12) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'ASTCHANDAHDI' is '1' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '1' [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Incrementing gosub_level [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'THISDIAL' is 'SIP/4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'ExecIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [zap2dahdi@macro-dial-one:1] ExecIf("SIP/MTelekomSIP1-00000010", "0?Return()") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: ExecIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'THISDIAL' (from 'THISDIAL}" = ""' len 8) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'THISDIAL' is 'SIP/4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [zap2dahdi@macro-dial-one:2] Set("SIP/MTelekomSIP1-00000010", "NEWDIAL=") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'THISDIAL' (from 'THISDIAL}' len 8) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'THISDIAL' is 'SIP/4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is '1' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [zap2dahdi@macro-dial-one:3] Set("SIP/MTelekomSIP1-00000010", "LOOPCNT2=1") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [zap2dahdi@macro-dial-one:4] Set("SIP/MTelekomSIP1-00000010", "ITER2=1") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'ITER2' is '1' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'THISDIAL' (from 'THISDIAL}' len 8) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'THISDIAL' is 'SIP/4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is 'SIP/4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [zap2dahdi@macro-dial-one:5] Set("SIP/MTelekomSIP1-00000010", "THISPART2=SIP/4113") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'THISPART2' is 'SIP/4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'THISPART2' is 'SIP/4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'ExecIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [zap2dahdi@macro-dial-one:6] ExecIf("SIP/MTelekomSIP1-00000010", "0?Set(THISPART2=DAHDI/4113)") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: ExecIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'THISPART2:0:3' (from 'THISPART2:0:3}" = "ZAP"' len 13) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'THISPART2' is 'SIP/4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'THISPART2:3' (from 'THISPART2:3})' len 11) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'THISPART2' is 'SIP/4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'NEWDIAL' is '' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'THISPART2' is 'SIP/4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [zap2dahdi@macro-dial-one:7] Set("SIP/MTelekomSIP1-00000010", "NEWDIAL=SIP/4113&") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'ITER2' is '1' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '2' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [zap2dahdi@macro-dial-one:8] Set("SIP/MTelekomSIP1-00000010", "ITER2=2") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'ITER2' is '2' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'LOOPCNT2' is '1' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'GotoIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [zap2dahdi@macro-dial-one:9] GotoIf("SIP/MTelekomSIP1-00000010", "0?begin2") in new stack [Oct 28 15:47:33] DEBUG[15438] pbx.c: Not taking any branch [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: GotoIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'NEWDIAL' is 'SIP/4113&' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is '9' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '8' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'NEWDIAL' is 'SIP/4113&' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [zap2dahdi@macro-dial-one:10] Set("SIP/MTelekomSIP1-00000010", "THISDIAL=SIP/4113") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Return' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [zap2dahdi@macro-dial-one:11] Return("SIP/MTelekomSIP1-00000010", "") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Return [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Decrementing gosub_level [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DSTRING' is '' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'THISDIAL' is 'SIP/4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [dstring@macro-dial-one:9] Set("SIP/MTelekomSIP1-00000010", "DSTRING=SIP/4113&") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'ITER' is '1' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '2' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [dstring@macro-dial-one:10] Set("SIP/MTelekomSIP1-00000010", "ITER=2") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'ITER' is '2' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'LOOPCNT' is '1' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'GotoIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [dstring@macro-dial-one:11] GotoIf("SIP/MTelekomSIP1-00000010", "0?begin") in new stack [Oct 28 15:47:33] DEBUG[15438] pbx.c: Not taking any branch [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: GotoIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DSTRING' is 'SIP/4113&' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is '9' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '8' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DSTRING' is 'SIP/4113&' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [dstring@macro-dial-one:12] Set("SIP/MTelekomSIP1-00000010", "DSTRING=SIP/4113") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Return' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [dstring@macro-dial-one:13] Return("SIP/MTelekomSIP1-00000010", "") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Return [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Decrementing gosub_level [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DSTRING' is 'SIP/4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is '8' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'GotoIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-dial-one:27] GotoIf("SIP/MTelekomSIP1-00000010", "0?nodial") in new stack [Oct 28 15:47:33] DEBUG[15438] pbx.c: Not taking any branch [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: GotoIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DEXTEN' is '4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '1' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'GotoIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-dial-one:28] GotoIf("SIP/MTelekomSIP1-00000010", "1?skiptrace") in new stack [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Goto (macro-dial-one,s,30) [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: GotoIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'NODEST' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'ARG2' is 'tr' [Oct 28 15:47:33] DEBUG[15438] func_strings.c: FUNCTION REGEX ((M[(]auto-blkvm[)]))(tr) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'ARG2' is 'tr' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'ARG2' is 'tr' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Function result is 'tr' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-dial-one:30] Set("SIP/MTelekomSIP1-00000010", "D_OPTIONS=tr") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'ALERT_INFO' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'ALERT_INFO' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'ExecIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-dial-one:31] ExecIf("SIP/MTelekomSIP1-00000010", "0?SIPAddHeader(Alert-Info: )") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: ExecIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'ALERT_INFO' (from 'ALERT_INFO}"!=""' len 10) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'ALERT_INFO' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'ALERT_INFO' (from 'ALERT_INFO})' len 10) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'ALERT_INFO' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'SIPADDHEADER' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'SIPADDHEADER' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'ExecIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-dial-one:32] ExecIf("SIP/MTelekomSIP1-00000010", "0?SIPAddHeader()") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: ExecIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'SIPADDHEADER' (from 'SIPADDHEADER}"!=""' len 12) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'SIPADDHEADER' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'SIPADDHEADER' (from 'SIPADDHEADER})' len 12) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'SIPADDHEADER' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'MOHCLASS' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'MOHCLASS' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'ExecIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-dial-one:33] ExecIf("SIP/MTelekomSIP1-00000010", "0?SetMusicOnHold()") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: ExecIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'MOHCLASS' (from 'MOHCLASS}"!=""' len 8) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'MOHCLASS' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'MOHCLASS' (from 'MOHCLASS})' len 8) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'MOHCLASS' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'QUEUEWAIT' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'GosubIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-dial-one:34] GosubIf("SIP/MTelekomSIP1-00000010", "0?qwait,1") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: GosubIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'QUEUEWAIT' (from 'QUEUEWAIT}"!=""' len 9) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'QUEUEWAIT' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'CWIGNORE' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-dial-one:35] Set("SIP/MTelekomSIP1-00000010", "__CWIGNORE=") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-dial-one:36] Set("SIP/MTelekomSIP1-00000010", "__KEEPCID=TRUE") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DSTRING' is 'SIP/4113' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'ARG1' is '""' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'D_OPTIONS' is 'tr' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Dial' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-dial-one:37] Dial("SIP/MTelekomSIP1-00000010", "SIP/4113,"",tr") in new stack [Oct 28 15:47:33] DEBUG[15438] chan_sip.c: Asked to create a SIP channel with formats: 0x8 (alaw) [Oct 28 15:47:33] VERBOSE[15438] netsock.c: == Using UDPTL TOS bits 184 [Oct 28 15:47:33] VERBOSE[15438] netsock.c: == Using UDPTL CoS mark 5 [Oct 28 15:47:33] DEBUG[15438] chan_sip.c: Allocating new SIP dialog for 054cf68c6a57987b091e183402e4fdf2@172.17.10.200:5060 - INVITE (No RTP) [Oct 28 15:47:33] DEBUG[15438] chan_sip.c: Cant create SIP call - target device not registered [Oct 28 15:47:33] DEBUG[15438] chan_sip.c: Destroying SIP dialog 054cf68c6a57987b091e183402e4fdf2@172.17.10.200:5060 [Oct 28 15:47:33] VERBOSE[15438] chan_sip.c: Really destroying SIP dialog '054cf68c6a57987b091e183402e4fdf2@172.17.10.200:5060' Method: INVITE [Oct 28 15:47:33] WARNING[15438] app_dial.c: Unable to create channel of type 'SIP' (cause 20 - Unknown) [Oct 28 15:47:33] VERBOSE[15438] app_dial.c: == Everyone is busy/congested at this time (1:0/0/1) [Oct 28 15:47:33] DEBUG[15438] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL. [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Dial [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DIALSTATUS_CW' is '' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DIALSTATUS_CW' is '' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'ExecIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-dial-one:38] ExecIf("SIP/MTelekomSIP1-00000010", "0?Set(DIALSTATUS=)") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: ExecIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'DIALSTATUS_CW' (from 'DIALSTATUS_CW}"!=""' len 13) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DIALSTATUS_CW' is '' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'DIALSTATUS_CW' (from 'DIALSTATUS_CW})' len 13) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DIALSTATUS_CW' is '' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'SCREEN' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DIALSTATUS' is 'CHANUNAVAIL' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DIALSTATUS' is 'CHANUNAVAIL' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'GosubIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-dial-one:39] GosubIf("SIP/MTelekomSIP1-00000010", "0?s-CHANUNAVAIL,1") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: GosubIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'SCREEN' (from 'SCREEN}"!=""|"${DIALSTATUS}"="ANSWER"' len 6) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'SCREEN' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'DIALSTATUS' (from 'DIALSTATUS}"="ANSWER"' len 10) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DIALSTATUS' is 'CHANUNAVAIL' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'DIALSTATUS' (from 'DIALSTATUS},1' len 10) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DIALSTATUS' is 'CHANUNAVAIL' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'MacroExit' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-dial-one:40] MacroExit("SIP/MTelekomSIP1-00000010", "") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Macro [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'VMBOX' is 'novm' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'SCREEN' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DIALSTATUS' is 'CHANUNAVAIL' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'GotoIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-exten-vm:10] GotoIf("SIP/MTelekomSIP1-00000010", "0?exit,return") in new stack [Oct 28 15:47:33] DEBUG[15438] pbx.c: Not taking any branch [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: GotoIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DIALSTATUS' is 'CHANUNAVAIL' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-exten-vm:11] Set("SIP/MTelekomSIP1-00000010", "SV_DIALSTATUS=CHANUNAVAIL") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'SV_DIALSTATUS' is 'CHANUNAVAIL' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'CFUEXT' is '' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'SCREEN' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'GosubIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-exten-vm:12] GosubIf("SIP/MTelekomSIP1-00000010", "0?docfu,1") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: GosubIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'SV_DIALSTATUS' (from 'SV_DIALSTATUS}"="NOANSWER" & "${CFUEXT}"!="" & "${SCREEN}"=""' len 13) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'SV_DIALSTATUS' is 'CHANUNAVAIL' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'CFUEXT' (from 'CFUEXT}"!="" & "${SCREEN}"=""' len 6) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'CFUEXT' is '' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'SCREEN' (from 'SCREEN}"=""' len 6) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'SCREEN' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'SV_DIALSTATUS' is 'CHANUNAVAIL' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'CFBEXT' is '' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'GosubIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-exten-vm:13] GosubIf("SIP/MTelekomSIP1-00000010", "0?docfb,1") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: GosubIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'SV_DIALSTATUS' (from 'SV_DIALSTATUS}"="BUSY" & "${CFBEXT}"!=""' len 13) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'SV_DIALSTATUS' is 'CHANUNAVAIL' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Evaluating 'CFBEXT' (from 'CFBEXT}"!=""' len 6) [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'CFBEXT' is '' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'SV_DIALSTATUS' is 'CHANUNAVAIL' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-exten-vm:14] Set("SIP/MTelekomSIP1-00000010", "DIALSTATUS=CHANUNAVAIL") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'VMBOX' is 'novm' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'NoOp' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-exten-vm:15] NoOp("SIP/MTelekomSIP1-00000010", "Voicemail is 'novm'") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Noop [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'VMBOX' is 'novm' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '1' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DIALSTATUS' is 'CHANUNAVAIL' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'GotoIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-exten-vm:16] GotoIf("SIP/MTelekomSIP1-00000010", "1?s-CHANUNAVAIL,1") in new stack [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Goto (macro-exten-vm,s-CHANUNAVAIL,1) [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: GotoIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'IVR_RETVM' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'IVR_CONTEXT' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'NoOp' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s-CHANUNAVAIL@macro-exten-vm:1] NoOp("SIP/MTelekomSIP1-00000010", "IVR_RETVM: IVR_CONTEXT: ") in new stack [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Noop [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'IVR_RETVM' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'IVR_CONTEXT' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '0' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'GotoIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s-CHANUNAVAIL@macro-exten-vm:2] GotoIf("SIP/MTelekomSIP1-00000010", "0?exit,1") in new stack [Oct 28 15:47:33] DEBUG[15438] pbx.c: Not taking any branch [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: GotoIf [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'PlayTones' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s-CHANUNAVAIL@macro-exten-vm:3] PlayTones("SIP/MTelekomSIP1-00000010", "congestion") in new stack [Oct 28 15:47:33] DEBUG[15438] channel.c: Set channel SIP/MTelekomSIP1-00000010 to write format slin [Oct 28 15:47:33] DEBUG[15438] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Oct 28 15:47:33] DEBUG[15438] channel.c: Prodding channel 'SIP/MTelekomSIP1-00000010' [Oct 28 15:47:33] DEBUG[15438] res_rtp_asterisk.c: Setting the marker bit due to a source update [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Playtones [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Congestion' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s-CHANUNAVAIL@macro-exten-vm:4] Congestion("SIP/MTelekomSIP1-00000010", "10") in new stack [Oct 28 15:47:33] VERBOSE[15438] chan_sip.c: <--- Reliably Transmitting (NAT) to 10.16.91.2:5060 ---> SIP/2.0 503 Service Unavailable Via: SIP/2.0/UDP 10.16.91.2:5060;branch=z9hG4bK-d8754z-b5c5c444aee54541-1---d8754z-;received=10.16.91.2;rport=5060 From: ;tag=69d53945703f6225749b640731962a73 To: ;tag=as72197df2 Call-ID: 0000115d4cc97f0d7af1eb1df0f0f0f0@10.35.1.1/1 CSeq: 101 INVITE Server: Asterisk PBX 1.8.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer X-Asterisk-HangupCause: Unknown X-Asterisk-HangupCauseCode: 20 Content-Length: 0 <------------> [Oct 28 15:47:33] DEBUG[15438] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #13966 [Oct 28 15:47:33] DEBUG[15438] chan_sip.c: Trying to put 'SIP/2.0 503' onto UDP socket destined for 10.16.91.2:5060 [Oct 28 15:47:33] DEBUG[15438] chan_sip.c: Setting SIP_ALREADYGONE on dialog 0000115d4cc97f0d7af1eb1df0f0f0f0@10.35.1.1/1 [Oct 28 15:47:33] DEBUG[15438] channel.c: Soft-Hanging up channel 'SIP/MTelekomSIP1-00000010' [Oct 28 15:47:33] DEBUG[24936] devicestate.c: No provider found, checking channel drivers for SIP - MTelekomSIP1 [Oct 28 15:47:33] DEBUG[24936] chan_sip.c: Checking device state for peer MTelekomSIP1 [Oct 28 15:47:33] DEBUG[24936] devicestate.c: Changing state for SIP/MTelekomSIP1 - state 1 (Not in use) [Oct 28 15:47:33] DEBUG[24936] devicestate.c: device 'SIP/MTelekomSIP1' state '1' [Oct 28 15:47:33] DEBUG[24970] app_queue.c: Device 'SIP/MTelekomSIP1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: __FROM_DID Value: +3696305254 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: from-trunk-custom-SIGNAL Extension: +3696305254 Priority: 2 Application: Gosub AppData: app-blacklist-check,s,1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: LOCAL(ARGC) Value: 0 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: app-blacklist-check Extension: s Priority: 1 Application: GotoIf AppData: 0?blacklisted Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: app-blacklist-check Extension: s Priority: 2 Application: Set AppData: CALLED_BLACKLIST=1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: CALLED_BLACKLIST Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: app-blacklist-check Extension: s Priority: 3 Application: Return AppData: Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: GOSUB_RETVAL Value: Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: from-trunk-custom-SIGNAL Extension: +3696305254 Priority: 3 Application: Set AppData: CHANNEL(language)=hu Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: from-trunk-custom-SIGNAL Extension: +3696305254 Priority: 4 Application: ExecIf AppData: 1 ?Set(CALLERID(name)=anonymous) Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: from-trunk-custom-SIGNAL Extension: +3696305254 Priority: 5 Application: Set AppData: __CALLINGPRES_SV=allowed_not_screened Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: __CALLINGPRES_SV Value: allowed_not_screened Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: from-trunk-custom-SIGNAL Extension: +3696305254 Priority: 6 Application: Set AppData: CALLERPRES()=allowed_not_screened Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: from-trunk-custom-SIGNAL Extension: +3696305254 Priority: 7 Application: Goto AppData: from-did-direct,4113,1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: from-did-direct Extension: 4113 Priority: 1 Application: Macro AppData: exten-vm,novm,4113 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_EXTEN Value: 4113 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_CONTEXT Value: from-did-direct Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_PRIORITY Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: ARG1 Value: novm Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: ARG2 Value: 4113 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-exten-vm Extension: s Priority: 1 Application: Macro AppData: user-callerid, Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_EXTEN Value: s Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_CONTEXT Value: macro-exten-vm Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_PRIORITY Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: ARG1 Value: Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-user-callerid Extension: s Priority: 1 Application: Set AppData: AMPUSER=anonymous Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: AMPUSER Value: anonymous Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-user-callerid Extension: s Priority: 2 Application: GotoIf AppData: 0?report Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-user-callerid Extension: s Priority: 3 Application: ExecIf AppData: 1?Set(REALCALLERIDNUM=anonymous) Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: REALCALLERIDNUM Value: anonymous Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-user-callerid Extension: s Priority: 4 Application: Set AppData: AMPUSER= Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: AMPUSER Value: Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-user-callerid Extension: s Priority: 5 Application: Set AppData: AMPUSERCIDNAME= Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: AMPUSERCIDNAME Value: Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-user-callerid Extension: s Priority: 6 Application: GotoIf AppData: 1?report Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-user-callerid Extension: s Priority: 10 Application: GotoIf AppData: 0?continue Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-user-callerid Extension: s Priority: 11 Application: Set AppData: __TTL=64 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: __TTL Value: 64 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-user-callerid Extension: s Priority: 12 Application: GotoIf AppData: 1?continue Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-user-callerid Extension: s Priority: 19 Application: NoOp AppData: Using CallerID "anonymous" Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: ARG1 Value: novm Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_EXTEN Value: 4113 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_CONTEXT Value: from-did-direct Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_PRIORITY Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-exten-vm Extension: s Priority: 2 Application: Set AppData: RingGroupMethod=none Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: RingGroupMethod Value: none Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-exten-vm Extension: s Priority: 3 Application: Set AppData: VMBOX=novm Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: VMBOX Value: novm Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-exten-vm Extension: s Priority: 4 Application: Set AppData: __EXTTOCALL=4113 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: __EXTTOCALL Value: 4113 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-exten-vm Extension: s Priority: 5 Application: Set AppData: CFUEXT= Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: CFUEXT Value: Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-exten-vm Extension: s Priority: 6 Application: Set AppData: CFBEXT= Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: CFBEXT Value: Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-exten-vm Extension: s Priority: 7 Application: Set AppData: RT="" Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: RT Value: "" Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-exten-vm Extension: s Priority: 8 Application: Macro AppData: record-enable,4113,IN Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_EXTEN Value: s Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_CONTEXT Value: macro-exten-vm Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_PRIORITY Value: 8 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: ARG1 Value: 4113 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: ARG2 Value: IN Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-record-enable Extension: s Priority: 1 Application: MacroExit AppData: Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: ARG1 Value: novm Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: ARG2 Value: 4113 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_EXTEN Value: 4113 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_CONTEXT Value: from-did-direct Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_PRIORITY Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-exten-vm Extension: s Priority: 9 Application: Macro AppData: dial-one,"",tr,4113 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_EXTEN Value: s Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_CONTEXT Value: macro-exten-vm Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_PRIORITY Value: 9 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: ARG1 Value: "" Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: ARG2 Value: tr Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: ARG3 Value: 4113 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: s Priority: 1 Application: Set AppData: DEXTEN=4113 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: DEXTEN Value: 4113 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: s Priority: 2 Application: Set AppData: DIALSTATUS_CW= Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: DIALSTATUS_CW Value: Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: s Priority: 3 Application: GosubIf AppData: 0?screen,1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: s Priority: 4 Application: GosubIf AppData: 0?cf,1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: s Priority: 5 Application: GotoIf AppData: 1?skip1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: s Priority: 8 Application: GotoIf AppData: 0?nodial Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: s Priority: 9 Application: GotoIf AppData: 0?continue Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: DB_RESULT Value: ENABLED Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: s Priority: 10 Application: Set AppData: EXTHASCW=ENABLED Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: EXTHASCW Value: ENABLED Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: s Priority: 11 Application: GotoIf AppData: 0?next1:cwinusebusy Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: s Priority: 23 Application: GotoIf AppData: 1?next3:continue Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: s Priority: 24 Application: ExecIf AppData: 0?Set(DIALSTATUS_CW=BUSY) Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: s Priority: 25 Application: GotoIf AppData: 0?nodial Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: s Priority: 26 Application: GosubIf AppData: 1?dstring,1:dlocal,1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: LOCAL(ARGC) Value: 0 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: dstring Priority: 1 Application: Set AppData: DSTRING= Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: DSTRING Value: Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: DB_RESULT Value: 4113 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: dstring Priority: 2 Application: Set AppData: DEVICES=4113 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: DEVICES Value: 4113 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: dstring Priority: 3 Application: ExecIf AppData: 0?Return() Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: dstring Priority: 4 Application: ExecIf AppData: 0?Set(DEVICES=113) Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: dstring Priority: 5 Application: Set AppData: LOOPCNT=1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: LOOPCNT Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: dstring Priority: 6 Application: Set AppData: ITER=1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: ITER Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: DB_RESULT Value: SIP/4113 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: dstring Priority: 7 Application: Set AppData: THISDIAL=SIP/4113 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: THISDIAL Value: SIP/4113 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: dstring Priority: 8 Application: GosubIf AppData: 1?zap2dahdi,1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: LOCAL(ARGC) Value: 0 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: zap2dahdi Priority: 1 Application: ExecIf AppData: 0?Return() Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: zap2dahdi Priority: 2 Application: Set AppData: NEWDIAL= Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: NEWDIAL Value: Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: zap2dahdi Priority: 3 Application: Set AppData: LOOPCNT2=1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: LOOPCNT2 Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: zap2dahdi Priority: 4 Application: Set AppData: ITER2=1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: ITER2 Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: zap2dahdi Priority: 5 Application: Set AppData: THISPART2=SIP/4113 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: THISPART2 Value: SIP/4113 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: zap2dahdi Priority: 6 Application: ExecIf AppData: 0?Set(THISPART2=DAHDI/4113) Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: zap2dahdi Priority: 7 Application: Set AppData: NEWDIAL=SIP/4113& Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: NEWDIAL Value: SIP/4113& Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: zap2dahdi Priority: 8 Application: Set AppData: ITER2=2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: ITER2 Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: zap2dahdi Priority: 9 Application: GotoIf AppData: 0?begin2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: zap2dahdi Priority: 10 Application: Set AppData: THISDIAL=SIP/4113 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: THISDIAL Value: SIP/4113 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: zap2dahdi Priority: 11 Application: Return AppData: Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: GOSUB_RETVAL Value: Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: dstring Priority: 9 Application: Set AppData: DSTRING=SIP/4113& Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: DSTRING Value: SIP/4113& Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: dstring Priority: 10 Application: Set AppData: ITER=2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: ITER Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: dstring Priority: 11 Application: GotoIf AppData: 0?begin Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: dstring Priority: 12 Application: Set AppData: DSTRING=SIP/4113 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: DSTRING Value: SIP/4113 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: dstring Priority: 13 Application: Return AppData: Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: GOSUB_RETVAL Value: Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: s Priority: 27 Application: GotoIf AppData: 0?nodial Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: s Priority: 28 Application: GotoIf AppData: 1?skiptrace Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: s Priority: 30 Application: Set AppData: D_OPTIONS=tr Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: D_OPTIONS Value: tr Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: s Priority: 31 Application: ExecIf AppData: 0?SIPAddHeader(Alert-Info: ) Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: s Priority: 32 Application: ExecIf AppData: 0?SIPAddHeader() Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: s Priority: 33 Application: ExecIf AppData: 0?SetMusicOnHold() Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: s Priority: 34 Application: GosubIf AppData: 0?qwait,1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: s Priority: 35 Application: Set AppData: __CWIGNORE= Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: __CWIGNORE Value: Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: s Priority: 36 Application: Set AppData: __KEEPCID=TRUE Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: __KEEPCID Value: TRUE Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: s Priority: 37 Application: Dial AppData: SIP/4113,"",tr Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: DIALSTATUS Value: Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: DIALEDPEERNUMBER Value: Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: DIALEDPEERNAME Value: Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: ANSWEREDTIME Value: Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: DIALEDTIME Value: Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: DIALSTATUS Value: CHANUNAVAIL Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Dial Privilege: call,all SubEvent: End Channel: SIP/MTelekomSIP1-00000010 UniqueID: 1288273653.16 DialStatus: CHANUNAVAIL [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: s Priority: 38 Application: ExecIf AppData: 0?Set(DIALSTATUS=) Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: s Priority: 39 Application: GosubIf AppData: 0?s-CHANUNAVAIL,1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-dial-one Extension: s Priority: 40 Application: MacroExit AppData: Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: ARG1 Value: novm Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: ARG2 Value: 4113 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_EXTEN Value: 4113 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_CONTEXT Value: from-did-direct Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_PRIORITY Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-exten-vm Extension: s Priority: 10 Application: GotoIf AppData: 0?exit,return Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-exten-vm Extension: s Priority: 11 Application: Set AppData: SV_DIALSTATUS=CHANUNAVAIL Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: SV_DIALSTATUS Value: CHANUNAVAIL Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-exten-vm Extension: s Priority: 12 Application: GosubIf AppData: 0?docfu,1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-exten-vm Extension: s Priority: 13 Application: GosubIf AppData: 0?docfb,1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-exten-vm Extension: s Priority: 14 Application: Set AppData: DIALSTATUS=CHANUNAVAIL Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: DIALSTATUS Value: CHANUNAVAIL Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-exten-vm Extension: s Priority: 15 Application: NoOp AppData: Voicemail is 'novm' Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-exten-vm Extension: s Priority: 16 Application: GotoIf AppData: 1?s-CHANUNAVAIL,1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-exten-vm Extension: s-CHANUNAVAIL Priority: 1 Application: NoOp AppData: IVR_RETVM: IVR_CONTEXT: Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-exten-vm Extension: s-CHANUNAVAIL Priority: 2 Application: GotoIf AppData: 0?exit,1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-exten-vm Extension: s-CHANUNAVAIL Priority: 3 Application: PlayTones AppData: congestion Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-exten-vm Extension: s-CHANUNAVAIL Priority: 4 Application: Congestion AppData: 10 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/MTelekomSIP1-00000010 ChannelState: 7 ChannelStateDesc: Busy CallerIDNum: anonymous CallerIDName: anonymous Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[15438] channel.c: Set channel SIP/MTelekomSIP1-00000010 to write format alaw [Oct 28 15:47:33] DEBUG[15438] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Spawn extension (macro-exten-vm,s-CHANUNAVAIL,4) exited non-zero on 'SIP/MTelekomSIP1-00000010' in macro 'exten-vm' [Oct 28 15:47:33] VERBOSE[15438] app_macro.c: == Spawn extension (macro-exten-vm, s-CHANUNAVAIL, 4) exited non-zero on 'SIP/MTelekomSIP1-00000010' in macro 'exten-vm' [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 0 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[15438] pbx.c: Spawn extension (from-did-direct,4113,1) exited non-zero on 'SIP/MTelekomSIP1-00000010' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: == Spawn extension (from-did-direct, 4113, 1) exited non-zero on 'SIP/MTelekomSIP1-00000010' [Oct 28 15:47:33] DEBUG[15438] channel.c: Soft-Hanging up channel 'SIP/MTelekomSIP1-00000010' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Macro' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [h@from-did-direct:1] Macro("SIP/MTelekomSIP1-00000010", "hangupcall,") in new stack [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: from-did-direct Extension: h Priority: 1 Application: Macro AppData: hangupcall, Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_IN_HANGUP Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_EXTEN Value: h Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_CONTEXT Value: from-did-direct Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_PRIORITY Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: ARG1 Value: Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'USE_CONFIRMATION' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'RINGGROUP_INDEX' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'CHANNEL' is 'SIP/MTelekomSIP1-00000010' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'UNIQCHAN' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '1' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'GotoIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-hangupcall:1] GotoIf("SIP/MTelekomSIP1-00000010", "1?skiprg") in new stack [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-hangupcall Extension: s Priority: 1 Application: GotoIf AppData: 1?skiprg Uniqueid: 1288273653.16 [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Goto (macro-hangupcall,s,4) [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: GotoIf [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'BLKVM_BASE' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'BLKVM_BASE' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'CHANNEL' is 'SIP/MTelekomSIP1-00000010' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'BLKVM_OVERRIDE' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '1' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'GotoIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-hangupcall:4] GotoIf("SIP/MTelekomSIP1-00000010", "1?skipblkvm") in new stack [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-hangupcall Extension: s Priority: 4 Application: GotoIf AppData: 1?skipblkvm Uniqueid: 1288273653.16 [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Goto (macro-hangupcall,s,7) [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: GotoIf [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'FMGRP' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'FMUNIQUE' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'CHANNEL' is 'SIP/MTelekomSIP1-00000010' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'FMUNIQUE' is NULL [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is '1' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'GotoIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-hangupcall:7] GotoIf("SIP/MTelekomSIP1-00000010", "1?theend") in new stack [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-hangupcall Extension: s Priority: 7 Application: GotoIf AppData: 1?theend Uniqueid: 1288273653.16 [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Goto (macro-hangupcall,s,9) [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: GotoIf [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'DIALSTATUS' is 'CHANUNAVAIL' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'HANGUPCAUSE' is '20' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'NoOp' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-hangupcall:9] NoOp("SIP/MTelekomSIP1-00000010", "Dialstatus:CHANUNAVAIL 20") in new stack [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-hangupcall Extension: s Priority: 9 Application: NoOp AppData: Dialstatus:CHANUNAVAIL 20 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Noop [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'SV_DIALSTATUS' is 'CHANUNAVAIL' [Oct 28 15:47:33] WARNING[15438] ast_expr2.fl: ast_yyerror(): syntax error: syntax error, unexpected '', expecting $end; Input: CHANUNAVAIL"="CHANUNAVAIL" ^ [Oct 28 15:47:33] WARNING[15438] ast_expr2.fl: If you have questions, please refer to doc/tex/channelvariables.tex. [Oct 28 15:47:33] DEBUG[15438] pbx.c: Expression result is 'CHANUNAVAIL' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'GotoIf' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-hangupcall:10] GotoIf("SIP/MTelekomSIP1-00000010", "CHANUNAVAIL?unvhngp") in new stack [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-hangupcall Extension: s Priority: 10 Application: GotoIf AppData: CHANUNAVAIL?unvhngp Uniqueid: 1288273653.16 [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Goto (macro-hangupcall,s,13) [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: GotoIf [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Set' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-hangupcall:13] Set("SIP/MTelekomSIP1-00000010", "HANGUPCAUSE="31"") in new stack [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-hangupcall Extension: s Priority: 13 Application: Set AppData: HANGUPCAUSE="31" Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: HANGUPCAUSE Value: "31" Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Set [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[15438] pbx.c: Result of 'HANGUPCAUSE' is '20' [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'NoOp' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-hangupcall:14] NoOp("SIP/MTelekomSIP1-00000010", "Hangupcause: 20") in new stack [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-hangupcall Extension: s Priority: 14 Application: NoOp AppData: Hangupcause: 20 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Executed application: Noop [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[15438] pbx.c: Launching 'Hangup' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: -- Executing [s@macro-hangupcall:15] Hangup("SIP/MTelekomSIP1-00000010", "31") in new stack [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Context: macro-hangupcall Extension: s Priority: 15 Application: Hangup AppData: 31 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[15438] app_macro.c: Spawn extension (macro-hangupcall,s,15) exited non-zero on 'SIP/MTelekomSIP1-00000010' in macro 'hangupcall' [Oct 28 15:47:33] VERBOSE[15438] app_macro.c: == Spawn extension (macro-hangupcall, s, 15) exited non-zero on 'SIP/MTelekomSIP1-00000010' in macro 'hangupcall' [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/MTelekomSIP1-00000010 Variable: MACRO_DEPTH Value: 0 Uniqueid: 1288273653.16 [Oct 28 15:47:33] DEBUG[15438] pbx.c: Spawn extension (from-did-direct,h,1) exited non-zero on 'SIP/MTelekomSIP1-00000010' [Oct 28 15:47:33] VERBOSE[15438] pbx.c: == Spawn extension (from-did-direct, h, 1) exited non-zero on 'SIP/MTelekomSIP1-00000010' [Oct 28 15:47:33] DEBUG[15438] channel.c: Hanging up channel 'SIP/MTelekomSIP1-00000010' [Oct 28 15:47:33] DEBUG[15438] chan_sip.c: Hangup call SIP/MTelekomSIP1-00000010, SIP callid 0000115d4cc97f0d7af1eb1df0f0f0f0@10.35.1.1/1 [Oct 28 15:47:33] DEBUG[15438] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x1dcc5fe8' [Oct 28 15:47:33] DEBUG[24973] manager.c: Examining event: Event: Hangup Privilege: call,all Channel: SIP/MTelekomSIP1-00000010 Uniqueid: 1288273653.16 CallerIDNum: anonymous CallerIDName: anonymous Cause: 31 Cause-txt: Normal, unspecified [Oct 28 15:47:33] DEBUG[24936] devicestate.c: No provider found, checking channel drivers for SIP - MTelekomSIP1 [Oct 28 15:47:33] DEBUG[24936] chan_sip.c: Checking device state for peer MTelekomSIP1 [Oct 28 15:47:33] DEBUG[24936] devicestate.c: Changing state for SIP/MTelekomSIP1 - state 1 (Not in use) [Oct 28 15:47:33] DEBUG[24936] devicestate.c: device 'SIP/MTelekomSIP1' state '1' [Oct 28 15:47:33] DEBUG[24970] app_queue.c: Device 'SIP/MTelekomSIP1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 28 15:47:33] VERBOSE[24959] chan_sip.c: <--- SIP read from UDP:10.16.91.2:5060 ---> ACK sip:+3696305254@172.17.10.200:5060 SIP/2.0 Via: SIP/2.0/UDP 10.16.91.2:5060;branch=z9hG4bK-d8754z-b5c5c444aee54541-1---d8754z-;rport Max-Forwards: 70 To: ;tag=as72197df2 From: ;tag=69d53945703f6225749b640731962a73 Call-ID: 0000115d4cc97f0d7af1eb1df0f0f0f0@10.35.1.1/1 CSeq: 101 ACK Allow: INVITE, CANCEL, ACK, BYE, REGISTER, OPTIONS, REFER, INFO, UPDATE User-Agent: Deverto Tequet SoftSwitch 6.3.0-pre1-bodnar Content-Length: 0 <-------------> [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Header 0 [ 46]: ACK sip:+3696305254@172.17.10.200:5060 SIP/2.0 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Header 1 [ 89]: Via: SIP/2.0/UDP 10.16.91.2:5060;branch=z9hG4bK-d8754z-b5c5c444aee54541-1---d8754z-;rport [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Header 3 [ 47]: To: ;tag=as72197df2 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Header 4 [ 76]: From: ;tag=69d53945703f6225749b640731962a73 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Header 5 [ 53]: Call-ID: 0000115d4cc97f0d7af1eb1df0f0f0f0@10.35.1.1/1 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Header 6 [ 13]: CSeq: 101 ACK [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Header 7 [ 71]: Allow: INVITE, CANCEL, ACK, BYE, REGISTER, OPTIONS, REFER, INFO, UPDATE [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Header 8 [ 55]: User-Agent: Deverto Tequet SoftSwitch 6.3.0-pre1-bodnar [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Oct 28 15:47:33] VERBOSE[24959] chan_sip.c: --- (10 headers 0 lines) --- [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: = Looking for Call ID: 0000115d4cc97f0d7af1eb1df0f0f0f0@10.35.1.1/1 (Checking From) --From tag 69d53945703f6225749b640731962a73 --To-tag as72197df2 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #13966 [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Stopping retransmission on '0000115d4cc97f0d7af1eb1df0f0f0f0@10.35.1.1/1' of Response 101: Match Found [Oct 28 15:47:33] DEBUG[24959] chan_sip.c: Destroying SIP dialog 0000115d4cc97f0d7af1eb1df0f0f0f0@10.35.1.1/1 [Oct 28 15:47:33] VERBOSE[24959] chan_sip.c: Really destroying SIP dialog '0000115d4cc97f0d7af1eb1df0f0f0f0@10.35.1.1/1' Method: ACK [Oct 28 15:47:33] DEBUG[24959] rtp_engine.c: Destroyed RTP instance '0x1dcc5fe8' [Oct 28 15:47:39] DEBUG[24959] chan_sip.c: Allocating new SIP dialog for 64efe5a83727aa745801b10b4f67fc89@172.17.10.200:5060 - OPTIONS (No RTP) [Oct 28 15:47:39] DEBUG[24959] acl.c: For destination '10.101.250.26', our source address is '10.101.10.205'. [Oct 28 15:47:39] DEBUG[24959] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.101.10.205:5060 [Oct 28 15:47:39] DEBUG[24959] chan_sip.c: Initializing initreq for method OPTIONS - callid 77757fd67c473e523b3ffae523904c34@10.101.10.205:5060 [Oct 28 15:47:39] DEBUG[24959] chan_sip.c: Header 0 [ 43]: OPTIONS sip:4113@10.101.250.26:5060 SIP/2.0 [Oct 28 15:47:39] DEBUG[24959] chan_sip.c: Header 1 [ 58]: Via: SIP/2.0/UDP 10.101.10.205:5060;branch=z9hG4bK666e4527 [Oct 28 15:47:39] DEBUG[24959] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Oct 28 15:47:39] DEBUG[24959] chan_sip.c: Header 3 [ 58]: From: "Unknown" ;tag=as3d599d81 [Oct 28 15:47:39] DEBUG[24959] chan_sip.c: Header 4 [ 33]: To: [Oct 28 15:47:39] DEBUG[24959] chan_sip.c: Header 5 [ 41]: Contact: [Oct 28 15:47:39] DEBUG[24959] chan_sip.c: Header 6 [ 60]: Call-ID: 77757fd67c473e523b3ffae523904c34@10.101.10.205:5060 [Oct 28 15:47:39] DEBUG[24959] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS [Oct 28 15:47:39] DEBUG[24959] chan_sip.c: Header 8 [ 30]: User-Agent: Asterisk PBX 1.8.0 [Oct 28 15:47:39] DEBUG[24959] chan_sip.c: Header 9 [ 35]: Date: Thu, 28 Oct 2010 13:47:39 GMT [Oct 28 15:47:39] DEBUG[24959] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Oct 28 15:47:39] DEBUG[24959] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Oct 28 15:47:39] VERBOSE[24959] chan_sip.c: Reliably Transmitting (no NAT) to 10.101.250.26:5060: OPTIONS sip:4113@10.101.250.26:5060 SIP/2.0 Via: SIP/2.0/UDP 10.101.10.205:5060;branch=z9hG4bK666e4527 Max-Forwards: 70 From: "Unknown" ;tag=as3d599d81 To: Contact: Call-ID: 77757fd67c473e523b3ffae523904c34@10.101.10.205:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.0 Date: Thu, 28 Oct 2010 13:47:39 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Oct 28 15:47:39] DEBUG[24959] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #13967 [Oct 28 15:47:39] DEBUG[24959] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.101.250.26:5060 [Oct 28 15:47:40] DEBUG[24959] chan_sip.c: SIP TIMER: Not rescheduling id #13967:OPTIONS (Method 3) (No timer T1) [Oct 28 15:47:40] VERBOSE[24959] chan_sip.c: Retransmitting #1 (no NAT) to 10.101.250.26:5060: OPTIONS sip:4113@10.101.250.26:5060 SIP/2.0 Via: SIP/2.0/UDP 10.101.10.205:5060;branch=z9hG4bK666e4527 Max-Forwards: 70 From: "Unknown" ;tag=as3d599d81 To: Contact: Call-ID: 77757fd67c473e523b3ffae523904c34@10.101.10.205:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.0 Date: Thu, 28 Oct 2010 13:47:39 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Oct 28 15:47:40] DEBUG[24959] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.101.250.26:5060 [Oct 28 15:47:41] DEBUG[24959] chan_sip.c: SIP TIMER: Not rescheduling id #13967:OPTIONS (Method 3) (No timer T1) [Oct 28 15:47:41] VERBOSE[24959] chan_sip.c: Retransmitting #2 (no NAT) to 10.101.250.26:5060: OPTIONS sip:4113@10.101.250.26:5060 SIP/2.0 Via: SIP/2.0/UDP 10.101.10.205:5060;branch=z9hG4bK666e4527 Max-Forwards: 70 From: "Unknown" ;tag=as3d599d81 To: Contact: Call-ID: 77757fd67c473e523b3ffae523904c34@10.101.10.205:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.0 Date: Thu, 28 Oct 2010 13:47:39 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Oct 28 15:47:41] DEBUG[24959] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.101.250.26:5060 [Oct 28 15:47:42] DEBUG[24959] chan_sip.c: SIP TIMER: Not rescheduling id #13967:OPTIONS (Method 3) (No timer T1) [Oct 28 15:47:42] VERBOSE[24959] chan_sip.c: Retransmitting #3 (no NAT) to 10.101.250.26:5060: OPTIONS sip:4113@10.101.250.26:5060 SIP/2.0 Via: SIP/2.0/UDP 10.101.10.205:5060;branch=z9hG4bK666e4527 Max-Forwards: 70 From: "Unknown" ;tag=as3d599d81 To: Contact: Call-ID: 77757fd67c473e523b3ffae523904c34@10.101.10.205:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.0 Date: Thu, 28 Oct 2010 13:47:39 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Oct 28 15:47:42] DEBUG[24959] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.101.250.26:5060 [Oct 28 15:47:43] DEBUG[24959] chan_sip.c: SIP TIMER: Not rescheduling id #13967:OPTIONS (Method 3) (No timer T1) [Oct 28 15:47:43] VERBOSE[24959] chan_sip.c: Retransmitting #4 (no NAT) to 10.101.250.26:5060: OPTIONS sip:4113@10.101.250.26:5060 SIP/2.0 Via: SIP/2.0/UDP 10.101.10.205:5060;branch=z9hG4bK666e4527 Max-Forwards: 70 From: "Unknown" ;tag=as3d599d81 To: Contact: Call-ID: 77757fd67c473e523b3ffae523904c34@10.101.10.205:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.0 Date: Thu, 28 Oct 2010 13:47:39 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Oct 28 15:47:43] DEBUG[24959] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.101.250.26:5060 [Oct 28 15:47:43] DEBUG[24959] chan_sip.c: Destroying SIP dialog 77757fd67c473e523b3ffae523904c34@10.101.10.205:5060 [Oct 28 15:47:43] VERBOSE[24959] chan_sip.c: Really destroying SIP dialog '77757fd67c473e523b3ffae523904c34@10.101.10.205:5060' Method: OPTIONS [Oct 28 15:47:45] DEBUG[24946] chan_iax2.c: ip callno count decremented to 0 for 192.168.159.225 [Oct 28 15:47:45] DEBUG[24947] chan_iax2.c: ip callno count incremented to 1 for 192.168.159.225 [Oct 28 15:47:45] DEBUG[24956] chan_iax2.c: schedule decrement of callno used for 192.168.159.225 in 60 seconds [Oct 28 15:47:45] DEBUG[24956] chan_iax2.c: Peer ForKisvardaAsterisk: got pong, lastms 65, historicms 65, maxms 2000 [Oct 28 15:47:53] VERBOSE[24959] chan_sip.c: Reliably Transmitting (no NAT) to 10.101.250.26:5060: OPTIONS sip:4113@10.101.250.26:5060 SIP/2.0 Via: SIP/2.0/UDP 10.101.10.205:5060;branch=z9hG4bK67a6906f Max-Forwards: 70 From: "Unknown" ;tag=as40ee6309 To: Contact: Call-ID: 5df947b93f645f4d7a3cfc5a3832fc81@10.101.10.205:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.0 Date: Thu, 28 Oct 2010 13:47:53 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Oct 28 15:47:54] VERBOSE[24959] chan_sip.c: Retransmitting #1 (no NAT) to 10.101.250.26:5060: OPTIONS sip:4113@10.101.250.26:5060 SIP/2.0 Via: SIP/2.0/UDP 10.101.10.205:5060;branch=z9hG4bK67a6906f Max-Forwards: 70 From: "Unknown" ;tag=as40ee6309 To: Contact: Call-ID: 5df947b93f645f4d7a3cfc5a3832fc81@10.101.10.205:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.0 Date: Thu, 28 Oct 2010 13:47:53 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Oct 28 15:47:55] VERBOSE[24959] chan_sip.c: Retransmitting #2 (no NAT) to 10.101.250.26:5060: OPTIONS sip:4113@10.101.250.26:5060 SIP/2.0 Via: SIP/2.0/UDP 10.101.10.205:5060;branch=z9hG4bK67a6906f Max-Forwards: 70 From: "Unknown" ;tag=as40ee6309 To: Contact: Call-ID: 5df947b93f645f4d7a3cfc5a3832fc81@10.101.10.205:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.0 Date: Thu, 28 Oct 2010 13:47:53 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 ---