!!! Please note, that this debug log was captured with aor contact=sip:vpbx400015767.mangosip.ru:5060 setting in pjsip.conf !!! [Sep 22 10:26:50] DEBUG[2382]: pjsip:0 : endpoint Request msg OPTIONS/cseq=49034 (tdta0x888cc30) created. [Sep 22 10:26:50] DEBUG[2382]: config.c:3544 ast_parse_arg: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Sep 22 10:26:50] DEBUG[2382]: config.c:3544 ast_parse_arg: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Sep 22 10:26:50] DEBUG[2382]: config.c:3544 ast_parse_arg: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Sep 22 10:26:50] DEBUG[2382]: res_pjsip.c:3075 endpt_send_request: 0x866df84: Wrapper created [Sep 22 10:26:50] DEBUG[2382]: res_pjsip.c:3106 endpt_send_request: 0x866df84: Set timer to 30000 msec [Sep 22 10:26:50] DEBUG[2382]: pjsip:0 : tsx0x888dc9c .Transaction created for Request msg OPTIONS/cseq=49034 (tdta0x888cc30) [Sep 22 10:26:50] DEBUG[2382]: pjsip:0 : tsx0x888dc9c Sending Request msg OPTIONS/cseq=49034 (tdta0x888cc30) in state Null [Sep 22 10:26:50] DEBUG[2382]: pjsip:0 : sip_resolve.c .Starting async DNS A query: target=vpbx400034059.mangosip.ru, transport=Unspecified, port=5060 [Sep 22 10:26:50] DEBUG[2382]: pjsip:0 : resolver.c .Nameserver 10.0.1.254:53 state changed Active --> Probing [Sep 22 10:26:50] DEBUG[2382]: pjsip:0 : resolver.c .Nameserver 10.0.10.254:53 state changed Active --> Probing [Sep 22 10:26:50] DEBUG[2382]: pjsip:0 : resolver.c .Transmitting 43 bytes to NS 0 (10.0.1.254:53): DNS A query for vpbx400034059.mangosip.ru: Success [Sep 22 10:26:50] DEBUG[2382]: pjsip:0 : resolver.c .Transmitting 43 bytes to NS 1 (10.0.10.254:53): DNS A query for vpbx400034059.mangosip.ru: Success [Sep 22 10:26:50] DEBUG[2382]: pjsip:0 : tsx0x888dc9c .State changed from Null to Calling, event=TX_MSG [Sep 22 10:26:50] DEBUG[2387]: pjsip:0 : resolver.c Received 174 bytes DNS response from 10.0.1.254:53 [Sep 22 10:26:50] DEBUG[2387]: pjsip:0 : resolver.c Nameserver 10.0.1.254:53 state changed Probing --> Active [Sep 22 10:26:50] DEBUG[2387]: res_pjsip_multihomed.c:157 multihomed_on_tx_message: Re-wrote Contact URI host/port to XXX.XX.XXX.XXX:5060 [Sep 22 10:26:50] DEBUG[2387]: pjsip:0 : resolver.c Received 174 bytes DNS response from 10.0.10.254:53 [Sep 22 10:26:50] DEBUG[2387]: pjsip:0 : resolver.c Nameserver 10.0.10.254:53 state changed Probing --> Active [Sep 22 10:26:50] DEBUG[2387]: pjsip:0 : resolver.c DNS response from 10.0.10.254:53 id=1 discarded [Sep 22 10:26:50] DEBUG[2387]: pjsip:0 : sip_endpoint.c Processing incoming message: Response msg 200/OPTIONS/cseq=49034 (rdata0xb50ad954) [Sep 22 10:26:50] DEBUG[2382]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Response msg 200/OPTIONS/cseq=49034 (rdata0xb52c86bc) [Sep 22 10:26:50] DEBUG[2382]: pjsip:0 : tsx0x888dc9c .Incoming Response msg 200/OPTIONS/cseq=49034 (rdata0xb52c86bc) in state Calling [Sep 22 10:26:50] DEBUG[2382]: pjsip:0 : tsx0x888dc9c ..State changed from Calling to Completed, event=RX_MSG [Sep 22 10:26:50] DEBUG[2382]: res_pjsip.c:2963 endpt_send_request_cb: 0x866df84: PJSIP tsx response received [Sep 22 10:26:50] DEBUG[2382]: res_pjsip.c:2976 endpt_send_request_cb: 0x866df84: Cancelling timer [Sep 22 10:26:50] DEBUG[2382]: res_pjsip.c:2986 endpt_send_request_cb: 0x866df84: Timer cancelled [Sep 22 10:26:50] DEBUG[2382]: config.c:3544 ast_parse_arg: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Sep 22 10:26:50] DEBUG[2382]: config.c:3544 ast_parse_arg: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Sep 22 10:26:50] DEBUG[2382]: config.c:3544 ast_parse_arg: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Sep 22 10:26:50] DEBUG[2382]: res_pjsip.c:3005 endpt_send_request_cb: 0x866df84: Callbacks executed [Sep 22 10:26:50] DEBUG[2382]: res_pjsip.c:3057 send_request_wrapper_destructor: 0x866df84: wrapper destroyed Contact mango2/sip:vpbx400034059.mangosip.ru:5060 is now Reachable. RTT: 22.497 msec [Sep 22 10:26:50] DEBUG[2361]: threadpool.c:508 grow: Increasing threadpool stasis-core's size by 1 [Sep 22 10:26:54] DEBUG[2382]: pjsip:0 : endpoint Request msg OPTIONS/cseq=9248 (tdta0xb508bc10) created. [Sep 22 10:26:54] DEBUG[2382]: config.c:3544 ast_parse_arg: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Sep 22 10:26:54] DEBUG[2382]: config.c:3544 ast_parse_arg: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Sep 22 10:26:54] DEBUG[2382]: config.c:3544 ast_parse_arg: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Sep 22 10:26:54] DEBUG[2382]: res_pjsip.c:3075 endpt_send_request: 0x907cfa4: Wrapper created [Sep 22 10:26:54] DEBUG[2382]: res_pjsip.c:3106 endpt_send_request: 0x907cfa4: Set timer to 30000 msec [Sep 22 10:26:54] DEBUG[2382]: pjsip:0 : tsx0x891dc6c .Transaction created for Request msg OPTIONS/cseq=9248 (tdta0xb508bc10) [Sep 22 10:26:54] DEBUG[2382]: pjsip:0 : tsx0x891dc6c Sending Request msg OPTIONS/cseq=9248 (tdta0xb508bc10) in state Null [Sep 22 10:26:54] DEBUG[2382]: pjsip:0 : sip_resolve.c .Starting async DNS A query: target=vpbx400015767.mangosip.ru, transport=Unspecified, port=5060 [Sep 22 10:26:54] DEBUG[2382]: pjsip:0 : resolver.c .Transmitting 43 bytes to NS 0 (10.0.1.254:53): DNS A query for vpbx400015767.mangosip.ru: Success [Sep 22 10:26:54] DEBUG[2382]: pjsip:0 : tsx0x891dc6c .State changed from Null to Calling, event=TX_MSG [Sep 22 10:26:54] DEBUG[2387]: pjsip:0 : resolver.c Received 174 bytes DNS response from 10.0.1.254:53 [Sep 22 10:26:54] DEBUG[2387]: pjsip:0 : resolver.c Nameserver 10.0.1.254:53 state changed Active --> Active [Sep 22 10:26:54] DEBUG[2387]: res_pjsip_multihomed.c:157 multihomed_on_tx_message: Re-wrote Contact URI host/port to XXX.XX.XXX.XXX:5060 [Sep 22 10:26:54] DEBUG[2387]: pjsip:0 : sip_endpoint.c Processing incoming message: Response msg 200/OPTIONS/cseq=9248 (rdata0xb50ad954) [Sep 22 10:26:54] DEBUG[2382]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Response msg 200/OPTIONS/cseq=9248 (rdata0xb53582b4) [Sep 22 10:26:54] DEBUG[2382]: pjsip:0 : tsx0x891dc6c .Incoming Response msg 200/OPTIONS/cseq=9248 (rdata0xb53582b4) in state Calling [Sep 22 10:26:54] DEBUG[2382]: pjsip:0 : tsx0x891dc6c ..State changed from Calling to Completed, event=RX_MSG [Sep 22 10:26:54] DEBUG[2382]: res_pjsip.c:2963 endpt_send_request_cb: 0x907cfa4: PJSIP tsx response received [Sep 22 10:26:54] DEBUG[2382]: res_pjsip.c:2976 endpt_send_request_cb: 0x907cfa4: Cancelling timer [Sep 22 10:26:54] DEBUG[2382]: res_pjsip.c:2986 endpt_send_request_cb: 0x907cfa4: Timer cancelled [Sep 22 10:26:54] DEBUG[2382]: config.c:3544 ast_parse_arg: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Sep 22 10:26:54] DEBUG[2382]: config.c:3544 ast_parse_arg: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Sep 22 10:26:54] DEBUG[2382]: config.c:3544 ast_parse_arg: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Sep 22 10:26:54] DEBUG[2382]: res_pjsip.c:3005 endpt_send_request_cb: 0x907cfa4: Callbacks executed [Sep 22 10:26:54] DEBUG[2382]: res_pjsip.c:3057 send_request_wrapper_destructor: 0x907cfa4: wrapper destroyed Contact mango/sip:vpbx400015767.mangosip.ru:5060 is now Reachable. RTT: 37.497 msec [Sep 22 10:26:54] DEBUG[2361]: threadpool.c:508 grow: Increasing threadpool stasis-core's size by 1 [Sep 22 10:26:55] DEBUG[2387]: pjsip:0 : tsx0x888dc9c Timeout timer event [Sep 22 10:26:55] DEBUG[2387]: pjsip:0 : tsx0x888dc9c .State changed from Completed to Terminated, event=TIMER [Sep 22 10:26:55] DEBUG[2387]: pjsip:0 : tsx0x888dc9c Timeout timer event [Sep 22 10:26:55] DEBUG[2387]: pjsip:0 : tsx0x888dc9c .State changed from Terminated to Destroyed, event=TIMER [Sep 22 10:26:55] DEBUG[2387]: pjsip:0 : tdta0x888cc30 ..Destroying txdata Request msg OPTIONS/cseq=49034 (tdta0x888cc30) [Sep 22 10:26:55] DEBUG[2387]: pjsip:0 : tsx0x888dc9c Transaction destroyed! [Sep 22 10:26:59] DEBUG[2387]: pjsip:0 : tsx0x891dc6c Timeout timer event [Sep 22 10:26:59] DEBUG[2387]: pjsip:0 : tsx0x891dc6c .State changed from Completed to Terminated, event=TIMER [Sep 22 10:26:59] DEBUG[2387]: pjsip:0 : tsx0x891dc6c Timeout timer event [Sep 22 10:26:59] DEBUG[2387]: pjsip:0 : tsx0x891dc6c .State changed from Terminated to Destroyed, event=TIMER [Sep 22 10:26:59] DEBUG[2387]: pjsip:0 : tdta0xb508bc10 ..Destroying txdata Request msg OPTIONS/cseq=9248 (tdta0xb508bc10) [Sep 22 10:26:59] DEBUG[2387]: pjsip:0 : tsx0x891dc6c Transaction destroyed! [Sep 22 10:27:02] DEBUG[2405]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 4 for 192.168.0.95 [Sep 22 10:27:02] DEBUG[2373]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 221 [Sep 22 10:27:02] DEBUG[2373]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 221 [Sep 22 10:27:02] DEBUG[2373]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 221? addr=192.168.0.95:4569, defaddr=(null) maxms=2000, lastms=23 [Sep 22 10:27:02] DEBUG[2373]: devicestate.c:473 do_state_change: Changing state for IAX2/221 - state 0 (Unknown) [Sep 22 10:27:04] DEBUG[2407]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.95 in 60 seconds [Sep 22 10:27:12] DEBUG[2385]: threadpool.c:1107 worker_idle: Worker thread idle timeout reached. Dying. [Sep 22 10:27:12] DEBUG[2386]: threadpool.c:1107 worker_idle: Worker thread idle timeout reached. Dying. [Sep 22 10:27:12] DEBUG[2384]: threadpool.c:1107 worker_idle: Worker thread idle timeout reached. Dying. [Sep 22 10:27:12] DEBUG[2381]: threadpool.c:968 worker_thread_destroy: Destroying worker thread 8 [Sep 22 10:27:12] DEBUG[2381]: threadpool.c:968 worker_thread_destroy: Destroying worker thread 9 [Sep 22 10:27:12] DEBUG[2381]: threadpool.c:968 worker_thread_destroy: Destroying worker thread 7 [Sep 22 10:27:12] DEBUG[2383]: threadpool.c:1107 worker_idle: Worker thread idle timeout reached. Dying. [Sep 22 10:27:12] DEBUG[2381]: threadpool.c:968 worker_thread_destroy: Destroying worker thread 6 [Sep 22 10:27:14] DEBUG[2389]: threadpool.c:1107 worker_idle: Worker thread idle timeout reached. Dying. [Sep 22 10:27:14] DEBUG[2359]: threadpool.c:968 worker_thread_destroy: Destroying worker thread 11 [Sep 22 10:27:14] DEBUG[2421]: threadpool.c:1107 worker_idle: Worker thread idle timeout reached. Dying. [Sep 22 10:27:14] DEBUG[2361]: threadpool.c:968 worker_thread_destroy: Destroying worker thread 12 [Sep 22 10:27:14] DEBUG[2422]: threadpool.c:1107 worker_idle: Worker thread idle timeout reached. Dying. [Sep 22 10:27:14] DEBUG[2361]: threadpool.c:968 worker_thread_destroy: Destroying worker thread 13 [Sep 22 10:27:15] DEBUG[2397]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.1.105 [Sep 22 10:27:15] DEBUG[2397]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.1.108 [Sep 22 10:27:15] DEBUG[2397]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 3 for 192.168.0.95 [Sep 22 10:27:15] DEBUG[2397]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.1.115 [Sep 22 10:27:15] DEBUG[2397]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.95 [Sep 22 10:27:15] DEBUG[2409]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.95 [Sep 22 10:27:15] DEBUG[2397]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 1 for 192.168.1.115 [Sep 22 10:27:15] DEBUG[2400]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 2 for 192.168.1.115 [Sep 22 10:27:15] DEBUG[2401]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.0.95 in 60 seconds [Sep 22 10:27:15] DEBUG[2401]: chan_iax2.c:11157 socket_process_helper: Peer 221: got pong, lastms 24, historicms 24, maxms 2000 [Sep 22 10:27:15] DEBUG[2397]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 1 for 192.168.1.105 [Sep 22 10:27:15] DEBUG[2403]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 2 for 192.168.1.105 [Sep 22 10:27:15] DEBUG[2397]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 1 for 192.168.1.108 [Sep 22 10:27:15] DEBUG[2404]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 2 for 192.168.1.108 [Sep 22 10:27:15] DEBUG[2405]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.1.105 in 60 seconds [Sep 22 10:27:15] DEBUG[2405]: chan_iax2.c:11157 socket_process_helper: Peer 203: got pong, lastms 47, historicms 47, maxms 2000 [Sep 22 10:27:15] DEBUG[2407]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.1.108 in 60 seconds [Sep 22 10:27:15] DEBUG[2407]: chan_iax2.c:11157 socket_process_helper: Peer 201: got pong, lastms 53, historicms 53, maxms 2000 [Sep 22 10:27:16] DEBUG[2405]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.1.115 [Sep 22 10:27:16] DEBUG[2373]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 222 [Sep 22 10:27:16] DEBUG[2373]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 222 [Sep 22 10:27:16] DEBUG[2373]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 222? addr=192.168.1.115:4569, defaddr=(null) maxms=2000, lastms=26 [Sep 22 10:27:16] DEBUG[2373]: devicestate.c:473 do_state_change: Changing state for IAX2/222 - state 0 (Unknown) [Sep 22 10:27:17] DEBUG[2397]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.0.95 [Sep 22 10:27:18] DEBUG[2407]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.1.108 [Sep 22 10:27:18] DEBUG[2373]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 201 [Sep 22 10:27:18] DEBUG[2373]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 201 [Sep 22 10:27:18] DEBUG[2373]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 201? addr=192.168.1.108:4569, defaddr=(null) maxms=2000, lastms=53 [Sep 22 10:27:18] DEBUG[2373]: devicestate.c:473 do_state_change: Changing state for IAX2/201 - state 0 (Unknown) [Sep 22 10:27:18] DEBUG[2409]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.1.115 in 60 seconds [Sep 22 10:27:20] DEBUG[2401]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.1.105 [Sep 22 10:27:20] DEBUG[2373]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 203 [Sep 22 10:27:20] DEBUG[2373]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 203 [Sep 22 10:27:20] DEBUG[2373]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 203? addr=192.168.1.105:4569, defaddr=(null) maxms=2000, lastms=47 [Sep 22 10:27:20] DEBUG[2373]: devicestate.c:473 do_state_change: Changing state for IAX2/203 - state 0 (Unknown) [Sep 22 10:27:20] DEBUG[2403]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.1.108 in 60 seconds [Sep 22 10:27:22] DEBUG[2405]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.1.105 in 60 seconds [Sep 22 10:27:31] DEBUG[2397]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.1.115 [Sep 22 10:27:32] DEBUG[2397]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.1.108 [Sep 22 10:27:34] DEBUG[2397]: chan_iax2.c:2695 peercnt_remove: ip callno count decremented to 2 for 192.168.1.105 [Sep 22 10:27:37] NOTICE[2406]: chan_iax2.c:12310 __iax2_poke_noanswer: Peer '222' is now UNREACHABLE! Time: 26 [Sep 22 10:27:37] DEBUG[2406]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.1.115 in 60 seconds [Sep 22 10:27:37] DEBUG[2361]: threadpool.c:508 grow: Increasing threadpool stasis-core's size by 1 [Sep 22 10:27:37] DEBUG[2416]: app_queue.c:2374 device_state_cb: Device 'IAX2/222' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue. [Sep 22 10:27:47] DEBUG[2400]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.1.115 [Sep 22 10:27:47] NOTICE[2401]: chan_iax2.c:11112 socket_process_helper: Peer '222' is now REACHABLE! Time: 17 [Sep 22 10:27:47] DEBUG[2401]: chan_iax2.c:3063 sched_delay_remove: schedule decrement of callno used for 192.168.1.115 in 60 seconds [Sep 22 10:27:47] DEBUG[2401]: chan_iax2.c:11157 socket_process_helper: Peer 222: got pong, lastms 17, historicms 17, maxms 2000 [Sep 22 10:27:47] DEBUG[2416]: app_queue.c:2374 device_state_cb: Device 'IAX2/222' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 22 10:27:50] DEBUG[2405]: chan_iax2.c:2663 peercnt_add: ip callno count incremented to 3 for 192.168.0.95 [Sep 22 10:27:50] DEBUG[2373]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for IAX2 - 221 [Sep 22 10:27:50] DEBUG[2373]: chan_iax2.c:14472 iax2_devicestate: Checking device state for device 221 [Sep 22 10:27:50] DEBUG[2373]: chan_iax2.c:14481 iax2_devicestate: Found peer. What's device state of 221? addr=192.168.0.95:4569, defaddr=(null) maxms=2000, lastms=24 [Sep 22 10:27:50] DEBUG[2373]: devicestate.c:473 do_state_change: Changing state for IAX2/221 - state 0 (Unknown) [Sep 22 10:27:50] DEBUG[2382]: pjsip:0 : endpoint Request msg OPTIONS/cseq=32675 (tdta0xb508bc10) created. [Sep 22 10:27:50] DEBUG[2382]: config.c:3544 ast_parse_arg: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Sep 22 10:27:50] DEBUG[2382]: config.c:3544 ast_parse_arg: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Sep 22 10:27:50] DEBUG[2382]: config.c:3544 ast_parse_arg: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Sep 22 10:27:50] DEBUG[2382]: res_pjsip.c:3075 endpt_send_request: 0x866df84: Wrapper created [Sep 22 10:27:50] DEBUG[2382]: res_pjsip.c:3106 endpt_send_request: 0x866df84: Set timer to 30000 msec [Sep 22 10:27:50] DEBUG[2382]: pjsip:0 : tsx0x891dc6c .Transaction created for Request msg OPTIONS/cseq=32675 (tdta0xb508bc10) [Sep 22 10:27:50] DEBUG[2382]: pjsip:0 : tsx0x891dc6c Sending Request msg OPTIONS/cseq=32675 (tdta0xb508bc10) in state Null [Sep 22 10:27:50] DEBUG[2382]: pjsip:0 : sip_resolve.c .Starting async DNS A query: target=vpbx400034059.mangosip.ru, transport=Unspecified, port=5060 [Sep 22 10:27:50] DEBUG[2382]: pjsip:0 : resolver.c .Picked up DNS A record for vpbx400034059.mangosip.ru from cache, ttl=31 [Sep 22 10:27:50] DEBUG[2382]: res_pjsip_multihomed.c:157 multihomed_on_tx_message: Re-wrote Contact URI host/port to XXX.XX.XXX.XXX:5060 [Sep 22 10:27:50] DEBUG[2382]: pjsip:0 : tsx0x891dc6c .State changed from Null to Calling, event=TX_MSG [Sep 22 10:27:50] DEBUG[2387]: pjsip:0 : sip_endpoint.c Processing incoming message: Response msg 200/OPTIONS/cseq=32675 (rdata0xb50ad954) [Sep 22 10:27:50] DEBUG[2382]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Response msg 200/OPTIONS/cseq=32675 (rdata0xb535fe74) [Sep 22 10:27:50] DEBUG[2382]: pjsip:0 : tsx0x891dc6c .Incoming Response msg 200/OPTIONS/cseq=32675 (rdata0xb535fe74) in state Calling [Sep 22 10:27:50] DEBUG[2382]: pjsip:0 : tsx0x891dc6c ..State changed from Calling to Completed, event=RX_MSG [Sep 22 10:27:50] DEBUG[2382]: res_pjsip.c:2963 endpt_send_request_cb: 0x866df84: PJSIP tsx response received [Sep 22 10:27:50] DEBUG[2382]: res_pjsip.c:2976 endpt_send_request_cb: 0x866df84: Cancelling timer [Sep 22 10:27:50] DEBUG[2382]: res_pjsip.c:2986 endpt_send_request_cb: 0x866df84: Timer cancelled [Sep 22 10:27:50] DEBUG[2382]: config.c:3544 ast_parse_arg: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Sep 22 10:27:50] DEBUG[2382]: config.c:3544 ast_parse_arg: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Sep 22 10:27:50] DEBUG[2382]: config.c:3544 ast_parse_arg: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Sep 22 10:27:50] DEBUG[2388]: res_pjsip/pjsip_configuration.c:230 persistent_endpoint_contact_status_observer: Contact sip:vpbx400034059.mangosip.ru:5060 status didn't change: Reachable, RTT: 18.428 msec [Sep 22 10:27:50] DEBUG[2382]: res_pjsip.c:3005 endpt_send_request_cb: 0x866df84: Callbacks executed [Sep 22 10:27:50] DEBUG[2382]: res_pjsip.c:3057 send_request_wrapper_destructor: 0x866df84: wrapper destroyed