Sep 13 23:39:15.622 [INFO ] PHN: WEB: Request 94/750/0: GET /fox.css HTTP/1.1 Sep 13 23:39:15.623 [INFO ] PHN: WEB: 94 Digest authentication Sep 13 23:39:15.988 [INFO ] PHN: LLDP: Skipped packet (420 bytes), not from router/bridge Sep 13 23:39:22.184 [DEBUG1] PHN: LID::key_pressed: origin key event, state 1 Sep 13 23:39:22.209 [DEBUG1] PHN: LID::key_pressed: origin key event, state 2 Sep 13 23:39:22.213 [DEBUG0] UXM: Request backlight for module -1 with value 15 Sep 13 23:39:22.214 [INFO ] GUI: GUI: Allocating channel 91, line 1 Sep 13 23:39:22.229 [NOTICE] CSTA: csta_cid = 91 phone_cid91 Sep 13 23:39:22.230 [DEBUG1] SIP: RTP: set_port - ports: 49152 65534, con 116 Sep 13 23:39:22.230 [DEBUG0] MEDIA: MediaIpc::rtpSetup: rtp: RP116 rtcp: RC116 start: 49152 end: 65534 Sep 13 23:39:22.232 [INFO ] SIP: Dialog 91/116/1 going to trying Sep 13 23:39:22.233 [INFO ] GUI: GUI: Line-Seize subscription was not sent Sep 13 23:39:22.233 [DEBUG0] MEDIA: MediaIpc::setSpeakerDefault: 4 11 Sep 13 23:39:22.235 [DEBUG1] PHN: Goto Best State from 'pIdle' (26), force 1 called-by start_dialing-862 Sep 13 23:39:22.235 [DEBUG1] PHN: Goto State 'Edit_number' (5) from' Idle' (26), MB 0, blocked 0 caller:goto_best_state-449 Sep 13 23:39:22.266 [DEBUG0] UXM: Request backlight for module -1 with value 15 Sep 13 23:39:22.282 [INFO ] PHN: entering gui_object::display_on_minibrowser() state=1, force_redraw=0 Sep 13 23:39:22.282 [DEBUG0] PHN: MbParser:: enter Sep 13 23:39:22.282 [DEBUG0] PHN: MbParser:: selected_tree = /IPPhoneBatch/ Sep 13 23:39:22.288 [INFO ] PHN: Xpath applies: /IPPhoneBatch/ Sep 13 23:39:22.288 [INFO ] PHN: Xpath contains unrecognized steps, aborting Sep 13 23:39:22.289 [INFO ] PHN: Xpath applies: /SnomIPPhoneBatch/ Sep 13 23:39:22.289 [INFO ] PHN: Xpath contains unrecognized steps, aborting Sep 13 23:39:22.289 [DEBUG0] PHN: MbParser:: found tree = IPPhoneBatch Sep 13 23:39:22.289 [DEBUG0] PHN: MbParserMainTag:: tree = IPPhoneBatch Sep 13 23:39:22.289 [DEBUG0] PHN: MbParserMainTag:: searching in subs Sep 13 23:39:22.290 [DEBUG0] PHN: MbParserMainTag:: faoun tree = IPPhoneMenu Sep 13 23:39:22.290 [DEBUG0] PHN: MbParserMainTag:: tree = IPPhoneMenu Sep 13 23:39:22.294 [WARN ] GUI: Minibrowser callback $/enter_number_fkey_list expecting vector result, but no vector callback defined Sep 13 23:39:22.300 [INFO ] PHN: Xpath applies: /* Sep 13 23:39:22.301 [DEBUG0] PHN: Xpath succesfully fetched: /* Sep 13 23:39:22.301 [DEBUG0] PHN: Xpath succesfully fetched: Sep 13 23:39:22.509 [DEBUG0] UXM: Request backlight for module -1 with value 15 Sep 13 23:39:22.510 [DEBUG0] PHN: TaskMon: LCS/36275527 PollEvent took 301 msecs, started Sep 13 23:39:22 Sep 13 23:39:22.514 [INFO ] PHN: entering gui_object::display_on_minibrowser() state=2, force_redraw=1 Sep 13 23:39:22.515 [DEBUG1] MEDIA: 2502822579 onPlayDtmf (0) time 2502822568 Sep 13 23:39:22.515 [DEBUG1] MEDIA: 2502822579 onPlayDtmf: timer pending 0 list size: 0 Sep 13 23:39:22.515 [DEBUG1] MEDIA: 2502822579 onPlayDtmf: start PlayDtmf_cb now Sep 13 23:39:22.516 [DEBUG1] MEDIA: 2502822579 PlayDtmf_cb: list size: 1 Sep 13 23:39:22.516 [DEBUG1] MEDIA: GetMsUntilNextDtmfPlay: time since last event: 473658404 Sep 13 23:39:22.516 [DEBUG1] MEDIA: GetMsUntilNextDtmfPlay: Current and last events are release events - ignore, no wait time needed Sep 13 23:39:22.517 [DEBUG1] MEDIA: 2502822580 PlayDtmf_cb: Found 2502822568 type 0 Sep 13 23:39:22.518 [DEBUG1] MEDIA: 2502822580 PlayDtmf_cb: got duplicate event type 0 Sep 13 23:39:22.518 [DEBUG1] MEDIA: 2502822580 PlayDtmf_cb: restart cb in 0 ms Sep 13 23:39:22.519 [DEBUG1] MEDIA: 2502822580 PlayDtmf_cb: list size: 0 Sep 13 23:39:22.519 [DEBUG0] MEDIA: Socket 0x28ace8/noname: state connected(5) Sep 13 23:39:22.519 [DEBUG0] MEDIA: Socket 0x28afd8/noname: state connected(5) Sep 13 23:39:22.520 [DEBUG1] PHN: LID::key_pressed: origin key event, state 1 Sep 13 23:39:22.521 [DEBUG0] UXM: Request backlight for module -1 with value 15 Sep 13 23:39:22.612 [DEBUG1] PHN: LID::key_pressed: origin key event, state 2 Sep 13 23:39:22.615 [DEBUG1] MEDIA: 2502822982 onPlayDtmf (0) time 2502822915 Sep 13 23:39:22.616 [DEBUG1] MEDIA: 2502822982 onPlayDtmf: timer pending 0 list size: 0 Sep 13 23:39:22.616 [DEBUG1] MEDIA: 2502822982 onPlayDtmf: start PlayDtmf_cb now Sep 13 23:39:22.617 [DEBUG1] MEDIA: 2502822982 PlayDtmf_cb: list size: 1 Sep 13 23:39:22.618 [DEBUG1] MEDIA: GetMsUntilNextDtmfPlay: time since last event: 473658807 Sep 13 23:39:22.618 [DEBUG1] MEDIA: GetMsUntilNextDtmfPlay: Current and last events are release events - ignore, no wait time needed Sep 13 23:39:22.618 [DEBUG1] MEDIA: 2502822983 PlayDtmf_cb: Found 2502822915 type 0 Sep 13 23:39:22.619 [DEBUG1] MEDIA: 2502822983 PlayDtmf_cb: got duplicate event type 0 Sep 13 23:39:22.619 [DEBUG1] MEDIA: 2502822983 PlayDtmf_cb: restart cb in 0 ms Sep 13 23:39:22.619 [DEBUG1] MEDIA: 2502822983 PlayDtmf_cb: list size: 0 Sep 13 23:39:22.671 [DEBUG1] PHN: LID::key_pressed: origin key event, state 1 Sep 13 23:39:22.672 [DEBUG0] UXM: Request backlight for module -1 with value 15 Sep 13 23:39:22.762 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:22.764 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:22.779 [INFO ] PHN: entering gui_object::display_on_minibrowser() state=1, force_redraw=1 Sep 13 23:39:22.779 [DEBUG0] PHN: MbParser:: enter Sep 13 23:39:22.779 [DEBUG0] PHN: MbParser:: selected_tree = /IPPhoneBatch/ Sep 13 23:39:22.785 [INFO ] PHN: Xpath applies: /IPPhoneBatch/ Sep 13 23:39:22.785 [INFO ] PHN: Xpath contains unrecognized steps, aborting Sep 13 23:39:22.785 [INFO ] PHN: Xpath applies: /SnomIPPhoneBatch/ Sep 13 23:39:22.785 [INFO ] PHN: Xpath contains unrecognized steps, aborting Sep 13 23:39:22.786 [DEBUG0] PHN: MbParser:: found tree = IPPhoneBatch Sep 13 23:39:22.786 [DEBUG0] PHN: MbParserMainTag:: tree = IPPhoneBatch Sep 13 23:39:22.786 [DEBUG0] PHN: MbParserMainTag:: searching in subs Sep 13 23:39:22.786 [DEBUG0] PHN: MbParserMainTag:: faoun tree = IPPhoneMenu Sep 13 23:39:22.787 [DEBUG0] PHN: MbParserMainTag:: tree = IPPhoneMenu Sep 13 23:39:22.791 [WARN ] GUI: Minibrowser callback $/enter_number_fkey_list expecting vector result, but no vector callback defined Sep 13 23:39:22.798 [INFO ] PHN: Xpath applies: /* Sep 13 23:39:22.798 [DEBUG0] PHN: Xpath succesfully fetched: /* Sep 13 23:39:22.798 [DEBUG0] PHN: Xpath succesfully fetched: Sep 13 23:39:23.006 [DEBUG1] PHN: LID::key_pressed: origin key event, state 2 Sep 13 23:39:23.009 [DEBUG0] PHN: LoopMon: LCS/36275532 took 247 (0) msecs, started Sep 13 23:39:22, 7 tasks Sep 13 23:39:23.010 [DEBUG1] MEDIA: 2502823376 onPlayDtmf (0) time 2502823181 Sep 13 23:39:23.010 [DEBUG1] MEDIA: 2502823376 onPlayDtmf: timer pending 0 list size: 0 Sep 13 23:39:23.011 [DEBUG1] MEDIA: 2502823376 onPlayDtmf: start PlayDtmf_cb now Sep 13 23:39:23.011 [DEBUG1] MEDIA: 2502823376 PlayDtmf_cb: list size: 1 Sep 13 23:39:23.012 [DEBUG1] MEDIA: GetMsUntilNextDtmfPlay: time since last event: 473659202 Sep 13 23:39:23.012 [DEBUG1] MEDIA: GetMsUntilNextDtmfPlay: Current and last events are release events - ignore, no wait time needed Sep 13 23:39:23.012 [DEBUG1] MEDIA: 2502823377 PlayDtmf_cb: Found 2502823181 type 0 Sep 13 23:39:23.013 [DEBUG1] MEDIA: 2502823377 PlayDtmf_cb: got duplicate event type 0 Sep 13 23:39:23.013 [DEBUG1] MEDIA: 2502823377 PlayDtmf_cb: restart cb in 0 ms Sep 13 23:39:23.014 [DEBUG1] MEDIA: 2502823377 PlayDtmf_cb: list size: 0 Sep 13 23:39:23.134 [DEBUG1] PHN: LID::key_pressed: origin key event, state 1 Sep 13 23:39:23.135 [DEBUG0] UXM: Request backlight for module -1 with value 15 Sep 13 23:39:23.272 [DEBUG1] PHN: LID::key_pressed: origin key event, state 2 Sep 13 23:39:23.275 [DEBUG1] MEDIA: 2502823642 onPlayDtmf (0) time 2502823639 Sep 13 23:39:23.276 [DEBUG1] MEDIA: 2502823642 onPlayDtmf: timer pending 0 list size: 0 Sep 13 23:39:23.276 [DEBUG1] MEDIA: 2502823642 onPlayDtmf: start PlayDtmf_cb now Sep 13 23:39:23.277 [DEBUG1] MEDIA: 2502823642 PlayDtmf_cb: list size: 1 Sep 13 23:39:23.278 [DEBUG1] MEDIA: GetMsUntilNextDtmfPlay: time since last event: 473659467 Sep 13 23:39:23.278 [DEBUG1] MEDIA: GetMsUntilNextDtmfPlay: Current and last events are release events - ignore, no wait time needed Sep 13 23:39:23.278 [DEBUG1] MEDIA: 2502823643 PlayDtmf_cb: Found 2502823639 type 0 Sep 13 23:39:23.279 [DEBUG1] MEDIA: 2502823643 PlayDtmf_cb: got duplicate event type 0 Sep 13 23:39:23.279 [DEBUG1] MEDIA: 2502823643 PlayDtmf_cb: restart cb in 0 ms Sep 13 23:39:23.279 [DEBUG1] MEDIA: 2502823643 PlayDtmf_cb: list size: 0 Sep 13 23:39:23.281 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:23.282 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:23.816 [NOTICE] LDAP: GetContacts search: str=*803, type_=PredictiveDialing, groups=[], fields=[], result_type=mixed, tbook_download=false, clear_cache=false, start_idx=, number_of_records=, custom_command= Sep 13 23:39:23.818 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:23.819 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:23.828 [INFO ] PHN: entering gui_object::display_on_minibrowser() state=2, force_redraw=1 Sep 13 23:39:23.828 [DEBUG0] PHN: MbParser:: enter Sep 13 23:39:23.828 [DEBUG0] PHN: MbParser:: selected_tree = /IPPhoneBatch/ Sep 13 23:39:23.834 [INFO ] PHN: Xpath applies: /IPPhoneBatch/ Sep 13 23:39:23.834 [INFO ] PHN: Xpath contains unrecognized steps, aborting Sep 13 23:39:23.835 [INFO ] PHN: Xpath applies: /SnomIPPhoneBatch/ Sep 13 23:39:23.835 [INFO ] PHN: Xpath contains unrecognized steps, aborting Sep 13 23:39:23.835 [DEBUG0] PHN: MbParser:: found tree = IPPhoneBatch Sep 13 23:39:23.835 [DEBUG0] PHN: MbParserMainTag:: tree = IPPhoneBatch Sep 13 23:39:23.835 [DEBUG0] PHN: MbParserMainTag:: searching in subs Sep 13 23:39:23.836 [DEBUG0] PHN: MbParserMainTag:: faoun tree = IPPhoneMenu Sep 13 23:39:23.836 [DEBUG0] PHN: MbParserMainTag:: tree = IPPhoneMenu Sep 13 23:39:23.841 [WARN ] GUI: Minibrowser callback $/enter_number_fkey_list expecting vector result, but no vector callback defined Sep 13 23:39:23.859 [INFO ] PHN: Xpath applies: /* Sep 13 23:39:23.860 [DEBUG0] PHN: Xpath succesfully fetched: /* Sep 13 23:39:23.860 [DEBUG0] PHN: Xpath succesfully fetched: Sep 13 23:39:24.093 [DEBUG1] PHN: LID::key_pressed: origin key event, state 1 Sep 13 23:39:24.094 [DEBUG0] PHN: LoopMon: LCS/36275560 took 267 (0) msecs, started Sep 13 23:39:23, 2 tasks Sep 13 23:39:24.163 [DEBUG1] PHN: LID::key_pressed: origin key event, state 2 Sep 13 23:39:24.166 [DEBUG0] UXM: Request backlight for module -1 with value 15 Sep 13 23:39:24.170 [DEBUG1] MEDIA: 2502824533 onPlayDtmf (0) time 2502824530 Sep 13 23:39:24.170 [DEBUG1] MEDIA: 2502824533 onPlayDtmf: timer pending 0 list size: 0 Sep 13 23:39:24.171 [DEBUG1] MEDIA: 2502824533 onPlayDtmf: start PlayDtmf_cb now Sep 13 23:39:24.171 [DEBUG1] MEDIA: 2502824534 PlayDtmf_cb: list size: 1 Sep 13 23:39:24.171 [DEBUG1] MEDIA: GetMsUntilNextDtmfPlay: time since last event: 473660359 Sep 13 23:39:24.172 [DEBUG1] MEDIA: GetMsUntilNextDtmfPlay: Current and last events are release events - ignore, no wait time needed Sep 13 23:39:24.172 [DEBUG1] MEDIA: 2502824534 PlayDtmf_cb: Found 2502824530 type 0 Sep 13 23:39:24.173 [DEBUG1] MEDIA: 2502824534 PlayDtmf_cb: got duplicate event type 0 Sep 13 23:39:24.173 [DEBUG1] MEDIA: 2502824534 PlayDtmf_cb: restart cb in 0 ms Sep 13 23:39:24.173 [DEBUG1] MEDIA: 2502824534 PlayDtmf_cb: list size: 0 Sep 13 23:39:24.272 [INFO ] PHN: entering gui_object::display_on_minibrowser() state=2, force_redraw=1 Sep 13 23:39:24.292 [INFO ] PHN: entering gui_object::display_on_minibrowser() state=1, force_redraw=1 Sep 13 23:39:24.293 [DEBUG0] PHN: MbParser:: enter Sep 13 23:39:24.293 [DEBUG0] PHN: MbParser:: selected_tree = /IPPhoneBatch/ Sep 13 23:39:24.299 [INFO ] PHN: Xpath applies: /IPPhoneBatch/ Sep 13 23:39:24.299 [INFO ] PHN: Xpath contains unrecognized steps, aborting Sep 13 23:39:24.299 [INFO ] PHN: Xpath applies: /SnomIPPhoneBatch/ Sep 13 23:39:24.299 [INFO ] PHN: Xpath contains unrecognized steps, aborting Sep 13 23:39:24.299 [DEBUG0] PHN: MbParser:: found tree = IPPhoneBatch Sep 13 23:39:24.300 [DEBUG0] PHN: MbParserMainTag:: tree = IPPhoneBatch Sep 13 23:39:24.300 [DEBUG0] PHN: MbParserMainTag:: searching in subs Sep 13 23:39:24.300 [DEBUG0] PHN: MbParserMainTag:: faoun tree = IPPhoneMenu Sep 13 23:39:24.300 [DEBUG0] PHN: MbParserMainTag:: tree = IPPhoneMenu Sep 13 23:39:24.305 [WARN ] GUI: Minibrowser callback $/enter_number_fkey_list expecting vector result, but no vector callback defined Sep 13 23:39:24.314 [INFO ] PHN: Xpath applies: /* Sep 13 23:39:24.314 [DEBUG0] PHN: Xpath succesfully fetched: /* Sep 13 23:39:24.314 [DEBUG0] PHN: Xpath succesfully fetched: Sep 13 23:39:24.528 [DEBUG0] PHN: LoopMon: LCS/36275589 took 235 (0) msecs, started Sep 13 23:39:24, 1 tasks Sep 13 23:39:24.529 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:24.531 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:24.696 [NOTICE] LDAP: GetContacts search: str=*803*, type_=PredictiveDialing, groups=[], fields=[], result_type=mixed, tbook_download=false, clear_cache=false, start_idx=, number_of_records=, custom_command= Sep 13 23:39:24.698 [INFO ] PHN: entering gui_object::display_on_minibrowser() state=2, force_redraw=1 Sep 13 23:39:24.698 [DEBUG0] PHN: MbParser:: enter Sep 13 23:39:24.698 [DEBUG0] PHN: MbParser:: selected_tree = /IPPhoneBatch/ Sep 13 23:39:24.704 [INFO ] PHN: Xpath applies: /IPPhoneBatch/ Sep 13 23:39:24.704 [INFO ] PHN: Xpath contains unrecognized steps, aborting Sep 13 23:39:24.704 [INFO ] PHN: Xpath applies: /SnomIPPhoneBatch/ Sep 13 23:39:24.704 [INFO ] PHN: Xpath contains unrecognized steps, aborting Sep 13 23:39:24.704 [DEBUG0] PHN: MbParser:: found tree = IPPhoneBatch Sep 13 23:39:24.705 [DEBUG0] PHN: MbParserMainTag:: tree = IPPhoneBatch Sep 13 23:39:24.705 [DEBUG0] PHN: MbParserMainTag:: searching in subs Sep 13 23:39:24.705 [DEBUG0] PHN: MbParserMainTag:: faoun tree = IPPhoneMenu Sep 13 23:39:24.706 [DEBUG0] PHN: MbParserMainTag:: tree = IPPhoneMenu Sep 13 23:39:24.710 [WARN ] GUI: Minibrowser callback $/enter_number_fkey_list expecting vector result, but no vector callback defined Sep 13 23:39:24.720 [INFO ] PHN: Xpath applies: /* Sep 13 23:39:24.720 [DEBUG0] PHN: Xpath succesfully fetched: /* Sep 13 23:39:24.720 [DEBUG0] PHN: Xpath succesfully fetched: Sep 13 23:39:24.937 [DEBUG0] PHN: LoopMon: LCS/36275594 took 240 (0) msecs, started Sep 13 23:39:24, 1 tasks Sep 13 23:39:25.042 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:25.044 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:25.520 [DEBUG1] PHN: LID::key_pressed: origin key event, state 1 Sep 13 23:39:25.521 [DEBUG0] UXM: Request backlight for module -1 with value 15 Sep 13 23:39:25.523 [DEBUG0] MEDIA: MediaIpc::setSpeakerDefault: 6 0 Sep 13 23:39:25.552 [DEBUG1] SIP: set_rtp_state: hold state: sendrecv holding: 0 moh: 0 Sep 13 23:39:25.553 [INFO ] SIP: RTP: set_audible(0/0 -> 1/1): RP116 changed=1, update_req=0, adr= Sep 13 23:39:25.553 [DEBUG0] MEDIA: MediaIpc::setStream: prot Udp ssrc 892790e5 rtp RP116 rtcp RC116 stream 0 r 1 w 1 dtmf inb 0 outb 0 outbpt 101 codec 0 length 160 ssrtp 0 Sep 13 23:39:25.553 [DEBUG0] MEDIA: MediaIpc::setStream: rtp addr: Udp:[::]:0 :rtcp addr: Udp:[::]:0 srtp: 0 ssrtp: 0 rfc3551: 1 tos: 160 keepalive: 1 Sep 13 23:39:25.553 [DEBUG0] MEDIA: rtpmap_packet: '' Sep 13 23:39:25.554 [DEBUG0] MEDIA: MediaIpc::rtpSymmetric: RP116 0 Sep 13 23:39:25.555 [INFO ] SIP: Send Invite(c = 0x198c6d0, moh 0, reuse_sdp 0) caller:StartCall-122 Sep 13 23:39:25.555 [DEBUG1] SIP: SDP: Dialog 91, sdp state idle -> offering Sep 13 23:39:25.558 [DEBUG1] SIP: Routing to outbound proxy: sip:pbx.test:5061;transport=tls Sep 13 23:39:25.559 [DEBUG1] SIP: RoutePendingPacket 1021940: entry=url ? sip:pbx.test:5061;transport=tls all 10 Sep 13 23:39:25.559 [DEBUG1] SIP: RoutePendingPacket 1021940: entry=a Tls:pbx.test:5061 all 10 Sep 13 23:39:25.559 [DEBUG1] SIP: RoutePendingPacket 1021940: entry=Tls:192.168.170.2:5061 all 10 Sep 13 23:39:25.560 [DEBUG0] SIP: Use Connection Tls:192.168.170.2:5061 for packet 1021940 Sep 13 23:39:25.560 [DEBUG0] SIP: send INVITE (1: 8af82063eb38-83287z7nmu1z) -> Tls:192.168.170.2:5061 Sep 13 23:39:25.570 [INFO ] SIP: Dialog 91/116/0 going to trying Sep 13 23:39:25.571 [NOTICE] PHN: Subscribe for call completion on Sep 13 23:39:25.573 [NOTICE] SIP: sip:Subscriptions::PushFront callid:8df82063f38b-0ad6xrwxgpj6 id:107 guiid: contact: exp:60 renew:0 Sep 13 23:39:25.574 [DEBUG0] SIP: refresh subscription 107 in 316 sec Sep 13 23:39:25.575 [DEBUG1] SIP: Routing to outbound proxy: sip:pbx.test:5061;transport=tls Sep 13 23:39:25.576 [DEBUG1] PHN: Goto State 'Calling' (6) from' Edit_number' (5), MB 1, blocked 0 caller:MakeCall-757 Sep 13 23:39:25.579 [DEBUG0] UXM: Request backlight for module -1 with value 15 Sep 13 23:39:25.595 [DEBUG0] UXM: Request backlight for module -1 with value 15 Sep 13 23:39:25.595 [DEBUG0] MEDIA: Synthesizer Command: PLAY 0 0 0 Sep 13 23:39:25.597 [INFO ] GUI: synth_silent: connected lines: 1 state: Calling inIdle: 0 inTerminated: 0 Sep 13 23:39:25.597 [INFO ] GUI: synth_silent: lines with call action: 1 Sep 13 23:39:25.599 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:25.600 [DEBUG0] PHN: Request lookup for number sip:*803*@pbx.test;user=phone Sep 13 23:39:25.606 [NOTICE] LDAP: GetContacts search: str=03*, type_=Final, groups=[], fields=[], result_type=mixed, tbook_download=false, clear_cache=false, start_idx=, number_of_records=, custom_command= Sep 13 23:39:25.608 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:25.610 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:25.611 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:25.626 [DEBUG1] SIP: RoutePendingPacket 1021941: entry=url ? sip:pbx.test:5061;transport=tls all 11 Sep 13 23:39:25.626 [DEBUG1] SIP: RoutePendingPacket 1021941: entry=a Tls:pbx.test:5061 all 11 Sep 13 23:39:25.626 [DEBUG1] SIP: RoutePendingPacket 1021941: entry=Tls:192.168.170.2:5061 all 11 Sep 13 23:39:25.627 [DEBUG0] SIP: Use Connection Tls:192.168.170.2:5061 for packet 1021941 Sep 13 23:39:25.628 [DEBUG0] SIP: send SUBSCRIBE (1: 8df82063f38b-0ad6xrwxgpj6) -> Tls:192.168.170.2:5061 Sep 13 23:39:25.655 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:25.730 [DEBUG0] MEDIA: UdpStream: 0 (1, 1) RP116 '' - 0 0 Sep 13 23:39:25.730 [DEBUG0] MEDIA: add ssrc 2301071589 for rtp socket RP116 Sep 13 23:39:25.730 [INFO ] MEDIA: setSynthProgram Sep 13 23:39:25.731 [DEBUG1] PHN: LID::key_pressed: origin key event, state 2 Sep 13 23:39:25.735 [DEBUG1] SIP: recv 100 INVITE (1: 8af82063eb38-83287z7nmu1z) <- Tls:192.168.170.2:5061 Sep 13 23:39:25.736 [DEBUG1] PHN: Goto Best State from 'pCalling' (6), force 0 called-by if_state-620 Sep 13 23:39:25.736 [DEBUG1] PHN: Goto State 'Calling' (6) from' Calling' (6), MB 0, blocked 0 caller:goto_best_state-472 Sep 13 23:39:25.745 [DEBUG1] PHN: Goto Best State from 'pCalling' (6), force 0 called-by IfCallerid-2023 Sep 13 23:39:25.745 [DEBUG1] PHN: Goto State 'Calling' (6) from' Calling' (6), MB 0, blocked 0 caller:goto_best_state-472 Sep 13 23:39:25.748 [DEBUG1] PHN: Goto Best State from 'pCalling' (6), force 0 called-by if_ringback-1798 Sep 13 23:39:25.748 [DEBUG1] PHN: Goto State 'Calling' (6) from' Calling' (6), MB 0, blocked 0 caller:goto_best_state-472 Sep 13 23:39:25.750 [DEBUG1] SIP: recv 404 SUBSCRIBE (1: 8df82063f38b-0ad6xrwxgpj6) <- Tls:192.168.170.2:5061 Sep 13 23:39:25.753 [DEBUG1] SIP: recv 100 INVITE (1: 8af82063eb38-83287z7nmu1z) <- Tls:192.168.170.2:5061 Sep 13 23:39:25.754 [DEBUG1] PHN: Goto Best State from 'pCalling' (6), force 0 called-by if_state-620 Sep 13 23:39:25.755 [DEBUG1] PHN: Goto State 'Calling' (6) from' Calling' (6), MB 0, blocked 0 caller:goto_best_state-472 Sep 13 23:39:25.764 [DEBUG1] PHN: Goto Best State from 'pCalling' (6), force 0 called-by IfCallerid-2023 Sep 13 23:39:25.765 [DEBUG1] PHN: Goto State 'Calling' (6) from' Calling' (6), MB 0, blocked 0 caller:goto_best_state-472 Sep 13 23:39:25.767 [DEBUG1] PHN: Goto Best State from 'pCalling' (6), force 0 called-by if_ringback-1798 Sep 13 23:39:25.768 [DEBUG1] PHN: Goto State 'Calling' (6) from' Calling' (6), MB 0, blocked 0 caller:goto_best_state-472 Sep 13 23:39:25.771 [DEBUG1] SIP: recv 200 INVITE (1: 8af82063eb38-83287z7nmu1z) <- Tls:192.168.170.2:5061 Sep 13 23:39:25.773 [INFO ] SIP: Dialog 91/116/1 going to confirmed Sep 13 23:39:25.774 [DEBUG1] PHN: Goto Best State from 'pCalling' (6), force 0 called-by if_state-620 Sep 13 23:39:25.774 [DEBUG1] PHN: Goto State 'Calling' (6) from' Calling' (6), MB 0, blocked 0 caller:goto_best_state-472 Sep 13 23:39:25.776 [DEBUG1] SIP: Routing to outbound proxy: sip:pbx.test:5061;transport=tls Sep 13 23:39:25.776 [DEBUG1] SIP: RoutePendingPacket 1021942: entry=url ? sip:pbx.test:5061;transport=tls all 12 Sep 13 23:39:25.776 [DEBUG1] SIP: RoutePendingPacket 1021942: entry=a Tls:pbx.test:5061 all 12 Sep 13 23:39:25.777 [DEBUG1] SIP: RoutePendingPacket 1021942: entry=Tls:192.168.170.2:5061 all 12 Sep 13 23:39:25.778 [DEBUG0] SIP: Use Connection Tls:192.168.170.2:5061 for packet 1021942 Sep 13 23:39:25.778 [DEBUG0] SIP: send ACK (1: 8af82063eb38-83287z7nmu1z) -> Tls:192.168.170.2:5061 Sep 13 23:39:25.780 [DEBUG0] MEDIA: RingOrEarlyMedia Command: ssrc: 892790e5 to: cmd: Sep 13 23:39:25.781 [INFO ] SIP: sip::StartSessionTimer: session refresh 116/8af82063eb38-83287z7nmu1z within 1800 secs by local UA Sep 13 23:39:25.789 [DEBUG1] PHN: Goto Best State from 'pCalling' (6), force 0 called-by IfCallerid-2023 Sep 13 23:39:25.790 [DEBUG1] PHN: Goto State 'Calling' (6) from' Calling' (6), MB 0, blocked 0 caller:goto_best_state-472 Sep 13 23:39:25.790 [DEBUG1] SIP: SDP: Dialog 91, sdp state offering -> idle Sep 13 23:39:25.790 [DEBUG0] SIP: process sdp 91 Sep 13 23:39:25.791 [DEBUG0] SIP: process sdp answer 91 Sep 13 23:39:25.791 [DEBUG1] PHN: SRTP tag=1, cipher=AES_CM_128_HMAC_SHA1_80, mki=, client SSRTP=false, session_param= Sep 13 23:39:25.792 [DEBUG0] SIP: SRTP enabled Sep 13 23:39:25.793 [NOTICE] SIP: RTP: set_destination RP116 adr=192.168.170.2:10034 Sep 13 23:39:25.793 [DEBUG1] SIP: process rfc3264(ids 116/91): sendrecv holding:0 state:3, gui_state3, 192.168.170.2 Sep 13 23:39:25.793 [DEBUG1] SIP: to state: sendrecv Sep 13 23:39:25.793 [DEBUG1] SIP: set_rtp_state: hold state: sendrecv holding: 0 moh: 0 Sep 13 23:39:25.794 [INFO ] SIP: RTP: set_audible(1/1 -> 1/1): RP116 changed=0, update_req=1, adr=192.168.170.2:10034 Sep 13 23:39:25.794 [DEBUG1] SIP: Using oldp channel for multicast-transmit Sep 13 23:39:25.794 [DEBUG0] MEDIA: MediaIpc::rtpStats: cseq: 190662 ssrc: 2301071589 name: RP116 stream: 0 vqidx: Sep 13 23:39:25.795 [DEBUG0] SIP: requesting call stats: 190662 in state confirmed Sep 13 23:39:25.795 [DEBUG0] MEDIA: MediaIpc::setStream: prot Udp ssrc 892790e5 rtp RP116 rtcp RC116 stream 0 r 1 w 1 dtmf inb 0 outb 0 outbpt 0 codec 9 length 160 ssrtp 0 Sep 13 23:39:25.795 [DEBUG0] MEDIA: MediaIpc::setStream: rtp addr: Udp:192.168.170.2:10034 :rtcp addr: Udp:[::]:0 srtp: 1 ssrtp: 0 rfc3551: 1 tos: 160 keepalive: 1 Sep 13 23:39:25.796 [DEBUG0] MEDIA: rtpmap_packet: '0909150108081501' Sep 13 23:39:25.796 [DEBUG0] MEDIA: MediaIpc::rtpSymmetric: RP116 0 Sep 13 23:39:25.797 [INFO ] SIP: GuiConnected(id 91, 3, 1) Sep 13 23:39:25.799 [NOTICE] SIP: Unsubscribe 8df82063f38b-0ad6xrwxgpj6 107 1076 Sep 13 23:39:25.800 [NOTICE] SIP: clone_subscription was called but renew set to false 8df8206333c3-jk9ipm38xp86 107 1076 Sep 13 23:39:25.800 [NOTICE] SIP: Expires set to 0 by send_subscribe Sep 13 23:39:25.800 [DEBUG0] SIP: refresh subscription 107 in 30 sec Sep 13 23:39:25.802 [DEBUG1] SIP: Routing to outbound proxy: sip:pbx.test:5061;transport=tls Sep 13 23:39:25.803 [DEBUG1] SIP: RoutePendingPacket 1021943: entry=url ? sip:pbx.test:5061;transport=tls all 13 Sep 13 23:39:25.803 [DEBUG1] SIP: RoutePendingPacket 1021943: entry=a Tls:pbx.test:5061 all 13 Sep 13 23:39:25.803 [DEBUG1] SIP: RoutePendingPacket 1021943: entry=Tls:192.168.170.2:5061 all 13 Sep 13 23:39:25.803 [DEBUG0] SIP: Use Connection Tls:192.168.170.2:5061 for packet 1021943 Sep 13 23:39:25.804 [DEBUG0] SIP: send SUBSCRIBE (2: 8df8206333c3-jk9ipm38xp86) -> Tls:192.168.170.2:5061 Sep 13 23:39:25.806 [DEBUG1] PHN: Goto Best State from 'pCalling' (6), force 0 called-by if_connected-1878 Sep 13 23:39:25.806 [DEBUG1] PHN: Goto State 'Connected' (9) from' Calling' (6), MB 0, blocked 0 caller:goto_best_state-500 Sep 13 23:39:25.834 [DEBUG0] UXM: Request backlight for module -1 with value 15 Sep 13 23:39:25.834 [DEBUG0] MEDIA: Synthesizer Command: PLAY 0 0 0 Sep 13 23:39:25.835 [INFO ] GUI: SetAudioPlaystate: 1 Sep 13 23:39:25.835 [DEBUG0] MEDIA: MediaIpc::SetupAudioDevice: audio_mode_handsfree 5 microfone_device_front 5 0 audio_playstate_rtp Sep 13 23:39:25.836 [DEBUG0] PHN: LoopMon: LCS/36275603 took 237 (0) msecs, started Sep 13 23:39:25, 13 tasks Sep 13 23:39:25.836 [NOTICE] PHN: TPL: Socket 94 idle/connect timeout Sep 13 23:39:25.836 [DEBUG1] TLS: 0x19ec5e8 SSL Alert write/0:warning:close notify Sep 13 23:39:25.838 [WARN ] MEDIA: CallStats: 2301071589 not found Sep 13 23:39:25.840 [DEBUG0] SIP: Response CallStats 190662 (1) state confirmed Sep 13 23:39:25.840 [DEBUG0] MEDIA: UdpStream: 0 (1, 1) RP116 '30393039313530313038303831353031' - 0 0 Sep 13 23:39:25.841 [DEBUG0] MEDIA: add ssrc 2301071589 for rtp socket RP116 Sep 13 23:39:25.842 [DEBUG0] MEDIA: Start/Change Call: 2301071589----- Sep 13 23:39:25.842 [DEBUG0] MEDIA: Start Streaming at 0/0 Sep 13 23:39:25.842 [INFO ] MEDIA: CAudioSubsystem::StopCall: 654321 Sep 13 23:39:25.847 [DEBUG1] SIP: recv UPDATE (15568: 8af82063eb38-83287z7nmu1z) <- Tls:192.168.170.2:5061 Sep 13 23:39:25.848 [DEBUG1] SIP: SDP: Dialog 91, sdp state idle -> answering Sep 13 23:39:25.848 [DEBUG1] SIP: SDP: Dialog 91, sdp state answering -> idle Sep 13 23:39:25.851 [DEBUG1] PHN: Goto Best State from 'pConnected' (9), force 0 called-by IfCallerid-2023 Sep 13 23:39:25.851 [DEBUG1] PHN: Goto State 'Connected' (9) from' Connected' (9), MB 0, blocked 0 caller:goto_best_state-500 Sep 13 23:39:25.852 [INFO ] SIP: sip::StartSessionTimer: session refresh 116/8af82063eb38-83287z7nmu1z within 1800 secs by local UA Sep 13 23:39:25.854 [DEBUG1] SIP: RoutePendingPacket 1021944: entry=Tls:192.168.170.2:5061 all 14 Sep 13 23:39:25.854 [DEBUG0] SIP: Use Connection Tls:192.168.170.2:5061 for packet 1021944 Sep 13 23:39:25.854 [DEBUG0] SIP: send 200 UPDATE (15568: 8af82063eb38-83287z7nmu1z) -> Tls:192.168.170.2:5061 Sep 13 23:39:25.859 [DEBUG1] SIP: recv 400 SUBSCRIBE (2: 8df8206333c3-jk9ipm38xp86) <- Tls:192.168.170.2:5061 Sep 13 23:39:25.861 [DEBUG0] PHN: Request lookup for number sip:*803*@pbx.test;user=phone Sep 13 23:39:25.869 [NOTICE] LDAP: GetContacts search: str=03*, type_=Final, groups=[], fields=[], result_type=mixed, tbook_download=false, clear_cache=false, start_idx=, number_of_records=, custom_command= Sep 13 23:39:25.976 [INFO ] MEDIA: StopCall: active channels: 0 Sep 13 23:39:25.976 [INFO ] MEDIA: StopCall: channel 0 active: 0 ssrc: 0 Sep 13 23:39:25.977 [INFO ] MEDIA: StopCall: channel 1 active: 0 ssrc: 0 Sep 13 23:39:25.980 [NOTICE] MEDIA: PlayCall ssrc:2301071589 active: 0 use new channel Sep 13 23:39:25.981 [INFO ] MEDIA: Can't determine device for current audio_mode_=0 Sep 13 23:39:25.981 [INFO ] MEDIA: Can't determine device for current audio_mode_=0 Sep 13 23:39:25.981 [INFO ] MEDIA: PlayCall: active channels: 1 Sep 13 23:39:25.982 [INFO ] MEDIA: PlayCall: channel 0 active: 1 ssrc: 2301071589 Sep 13 23:39:25.982 [INFO ] MEDIA: PlayCall: channel 1 active: 0 ssrc: 0 Sep 13 23:39:25.983 [INFO ] MEDIA: setSynthProgram Sep 13 23:39:25.984 [INFO ] MEDIA: 2502826347 onSetupAudioDevice: 6 5 - 5 0 - 1 Sep 13 23:39:25.984 [INFO ] MEDIA: playstate 0->1 Sep 13 23:39:25.985 [INFO ] MEDIA: CAudioSubsystem::setAudioMode 0->6 Sep 13 23:39:26.098 [DEBUG0] MEDIA: MediaIpc::sendUdpPdu: name: RP116 remote: 192.168.170.2:10034 len: 56 Sep 13 23:39:26.100 [DEBUG0] MEDIA: found stream without packet ssrc Sep 13 23:39:26.100 [DEBUG0] MEDIA: set stream packet ssrc 1297896780 Sep 13 23:39:26.101 [INFO ] MEDIA: HandleChangedPacketSsrc: set first ssrc 1297896780 Sep 13 23:39:26.102 [DEBUG1] SIP: connection::OnMediaReceived: initial RTP packet received on connection 116 Sep 13 23:39:26.124 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:26.127 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:26.653 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:26.655 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:27.173 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:27.175 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:27.693 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:27.695 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:28.213 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:28.215 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:28.733 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:28.735 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:29.253 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:29.255 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:29.773 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:29.775 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:30.293 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:30.295 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:30.813 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:30.815 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:31.333 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:31.335 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:31.876 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:31.880 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:32.393 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:32.395 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:32.913 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:32.915 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:33.433 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:33.435 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:33.953 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:33.955 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:34.473 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:34.475 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:34.993 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:34.995 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:35.513 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:35.515 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:35.888 [INFO ] PHN: LLDP: No Voice Application Type TLV packet found. Sep 13 23:39:36.033 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:36.035 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:36.553 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:36.555 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:37.073 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:37.075 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:37.232 [NOTICE] SIP: sip:Subscriptions::Erase sip::subscription_refresh callid:41f620639d25-ssoi2oajitgo id:101 guiid:1070 contact: Sep 13 23:39:37.593 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:37.595 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:38.052 [DEBUG1] SIP: remove receive packet: 20566, all 14 Sep 13 23:39:38.072 [DEBUG1] SIP: remove receive packet: 20567, all 13 Sep 13 23:39:38.081 [DEBUG1] SIP: remove receive packet: 20568, all 12 Sep 13 23:39:38.092 [DEBUG1] SIP: remove receive packet: 20569, all 11 Sep 13 23:39:38.125 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:38.128 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:38.136 [DEBUG1] SIP: remove receive packet: 20570, all 10 Sep 13 23:39:38.181 [DEBUG1] SIP: remove receive packet: 20571, all 9 Sep 13 23:39:38.201 [DEBUG1] SIP: remove receive packet: 20572, all 8 Sep 13 23:39:38.642 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:38.646 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:38.875 [DEBUG1] PHN: Sending Keepalive to Watchdog Sep 13 23:39:38.879 [INFO ] PHN: HandleWatchdog: status: 1 -> 1, timeout: 60, dog_fd: 5, setting set: 0 value: Sep 13 23:39:39.155 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:39.159 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:39.673 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:39.675 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:40.185 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:40.188 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:40.702 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:40.705 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:41.071 [DEBUG1] SIP: remove pending packet: 1021932, all 14 Sep 13 23:39:41.091 [DEBUG1] SIP: remove pending packet: 1021935, all 13 Sep 13 23:39:41.201 [DEBUG1] SIP: remove pending packet: 1021937, all 12 Sep 13 23:39:41.222 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:41.225 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:41.742 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:41.745 [DEBUG0] PHN: ContactUtils::GetVcard: identity=1 Sep 13 23:39:42.094 [DEBUG1] SIP: recv BYE (15569: 8af82063eb38-83287z7nmu1z) <- Tls:192.168.170.2:5061 Sep 13 23:39:42.095 [INFO ] SIP: Dialog 91/116/4 going to terminated Sep 13 23:39:42.095 [DEBUG1] SIP: mark for deletion 116/8af82063eb38-83287z7nmu1z, cbi 0, 1 Sep 13 23:39:42.095 [INFO ] SIP: packet 1021940 stopped retransmission Sep 13 23:39:42.096 [DEBUG0] MEDIA: MediaIpc::rtpStats: cseq: 190685 ssrc: 2301071589 name: RP116 stream: 0 vqidx: 0 Sep 13 23:39:42.099 [DEBUG0] SIP: requesting call stats: 190685 in state terminated Sep 13 23:39:42.101 [DEBUG0] SIP: Response CallStats 190685 (2) state terminated Sep 13 23:39:42.103 [DEBUG1] SIP: RoutePendingPacket 1021945: entry=Tls:192.168.170.2:5061 all 12 Sep 13 23:39:42.104 [DEBUG0] SIP: Use Connection Tls:192.168.170.2:5061 for packet 1021945 Sep 13 23:39:42.104 [DEBUG0] SIP: send 200 BYE (15569: 8af82063eb38-83287z7nmu1z) -> Tls:192.168.170.2:5061 Sep 13 23:39:42.106 [DEBUG1] SIP: set_rtp_state: hold state: inactive holding: 0 moh: 0 Sep 13 23:39:42.106 [INFO ] SIP: RTP: set_audible(1/1 -> 0/0): RP116 changed=1, update_req=0, adr=192.168.170.2:10034 Sep 13 23:39:42.107 [INFO ] SIP: RTP: close stream 1, stats 0 Sep 13 23:39:42.108 [DEBUG0] MEDIA: MediaIpc::holdStream: prot: Udp ssrc: 892790e5 rtp: RP116 rtcp: RC116 stream: 0 holdstate: 0 Sep 13 23:39:42.115 [DEBUG0] MEDIA: MediaIpc::rtpSymmetric: RP116 0 Sep 13 23:39:42.116 [NOTICE] SIP: RTP: set_destination RP116 adr= Sep 13 23:39:42.117 [DEBUG0] GUI: Line 91: EndCall (1) Sep 13 23:39:42.119 [INFO ] SIP: onhook(91) Sep 13 23:39:42.120 [DEBUG1] PHN: Goto Best State from 'pConnected' (9), force 1 called-by SipReportsEndOfIncomingCall-1538 Sep 13 23:39:42.121 [DEBUG1] PHN: Goto State 'Terminated' (12) from' Connected' (9), MB 0, blocked 0 caller:goto_best_state-530 Sep 13 23:39:42.149 [DEBUG0] UXM: Request backlight for module -1 with value 15 Sep 13 23:39:42.151 [DEBUG0] MEDIA: Synthesizer Command: PLAY 0 0 0 Sep 13 23:39:42.152 [INFO ] GUI: synth_silent: connected lines: 1 state: Terminated inIdle: 0 inTerminated: 1 Sep 13 23:39:42.153 [INFO ] GUI: synth_silent: lines with call action: 0 Sep 13 23:39:42.153 [INFO ] GUI: synth_silent: set playstate idle and audio mode to none Sep 13 23:39:42.153 [INFO ] GUI: SetAudioPlaystate: 0 Sep 13 23:39:42.153 [DEBUG0] MEDIA: MediaIpc::SetupAudioDevice: audio_mode_none 0 microfone_device_front 5 0 audio_playstate_idle Sep 13 23:39:42.166 [DEBUG1] PHN: Goto State 'Minibrowser_Message' (25) from' Terminated' (12), MB 0, blocked 0 caller:ShowMessage-215 Sep 13 23:39:42.185 [DEBUG0] UXM: Request backlight for module -1 with value 15 Sep 13 23:39:42.192 [INFO ] PHN: entering gui_object::display_on_minibrowser() state=1, force_redraw=0 Sep 13 23:39:42.193 [DEBUG0] PHN: MbParser:: enter Sep 13 23:39:42.193 [DEBUG0] PHN: MbParser:: selected_tree = /IPPhoneBatch/ Sep 13 23:39:42.195 [INFO ] PHN: Xpath applies: /IPPhoneBatch/ Sep 13 23:39:42.195 [INFO ] PHN: Xpath contains unrecognized steps, aborting Sep 13 23:39:42.196 [INFO ] PHN: Xpath applies: /SnomIPPhoneBatch/ Sep 13 23:39:42.196 [INFO ] PHN: Xpath contains unrecognized steps, aborting Sep 13 23:39:42.196 [DEBUG0] PHN: MbParser:: found tree = IPPhoneBatch Sep 13 23:39:42.196 [DEBUG0] PHN: MbParserMainTag:: tree = IPPhoneBatch Sep 13 23:39:42.196 [DEBUG0] PHN: MbParserMainTag:: searching in subs Sep 13 23:39:42.197 [DEBUG0] PHN: MbParserMainTag:: faoun tree = IPPhoneMenu Sep 13 23:39:42.198 [DEBUG0] PHN: MbParserMainTag:: tree = IPPhoneMenu Sep 13 23:39:42.202 [INFO ] PHN: Xpath applies: /* Sep 13 23:39:42.202 [DEBUG0] PHN: Xpath succesfully fetched: /* Sep 13 23:39:42.202 [DEBUG0] PHN: Xpath succesfully fetched: Sep 13 23:39:42.309 [DEBUG0] UXM: Request backlight for module -1 with value 15 Sep 13 23:39:42.310 [DEBUG1] SIP: mark for deletion 116/8af82063eb38-83287z7nmu1z, cbi 1, 1 Sep 13 23:39:42.310 [INFO ] SIP: packet 1021940 stopped retransmission Sep 13 23:39:42.311 [DEBUG0] SIP: SipIcmpDataCb: local/remote=Icmp:0.0.0.0:51802/Icmp:192.168.170.2:10034 Sep 13 23:39:42.328 [INFO ] PHN: entering gui_object::display_on_minibrowser() state=2, force_redraw=0 Sep 13 23:39:42.386 [DEBUG0] SIP: connection 91 terminated Sep 13 23:39:42.386 [INFO ] SIP: RTP: set_audible(0/0 -> 0/0): RP116 changed=0, update_req=1, adr= Sep 13 23:39:42.386 [DEBUG0] MEDIA: MediaIpc::closeStream: 892790e5 Sep 13 23:39:42.387 [INFO ] SIP: rtp_port::release_turn_resources(), rtp relay port=0, rtcp relay port=0 Sep 13 23:39:42.388 [INFO ] SIP: RTP: set_audible(0/0 -> 0/0): RP116 changed=0, update_req=1, adr= Sep 13 23:39:42.388 [NOTICE] MEDIA: MediaIpc::rtpClose: RP116 Sep 13 23:39:42.388 [NOTICE] MEDIA: MediaIpc::rtpClose: RC116 Sep 13 23:39:42.389 [DEBUG0] MEDIA: UdpStream: 0 (0, 0) RP116 '' - 1 0 Sep 13 23:39:42.389 [DEBUG0] MEDIA: Stop Call: 2301071589----- Sep 13 23:39:42.389 [DEBUG0] MEDIA: Stop Streaming at 806/2187721031 Sep 13 23:39:42.390 [INFO ] MEDIA: pause call 2301071589 Sep 13 23:39:42.390 [INFO ] MEDIA: setSynthProgram Sep 13 23:39:42.391 [INFO ] MEDIA: 2502842523 onSetupAudioDevice: 0 0 - 5 0 - 0 Sep 13 23:39:42.391 [INFO ] MEDIA: CAudioSubsystem::setAudioMode 6->0 Sep 13 23:39:42.392 [INFO ] MEDIA: Can't determine device for current audio_mode_=0 Sep 13 23:39:42.392 [INFO ] MEDIA: Can't determine device for current audio_mode_=0 Sep 13 23:39:42.393 [INFO ] MEDIA: playstate 1->0 Sep 13 23:39:42.393 [DEBUG1] MEDIA: ClearAllCalls: clear 0 2301071589 Sep 13 23:39:42.394 [INFO ] MEDIA: CAudioSubsystem::StopCall: 2301071589 Sep 13 23:39:42.409 [NOTICE] MEDIA: PlayCall ssrc:654321 active: 0 use new channel Sep 13 23:39:42.512 [INFO ] MEDIA: halAudioSetPower deep sleep invoked Sep 13 23:39:42.553 [INFO ] MEDIA: halAudioSetPower full power invoked Sep 13 23:39:42.553 [INFO ] MEDIA: Can't determine device for current audio_mode_=0 Sep 13 23:39:42.553 [INFO ] MEDIA: Can't determine device for current audio_mode_=0 Sep 13 23:39:42.554 [INFO ] MEDIA: PlayCall: active channels: 1 Sep 13 23:39:42.554 [INFO ] MEDIA: PlayCall: channel 0 active: 1 ssrc: 654321 Sep 13 23:39:42.554 [INFO ] MEDIA: PlayCall: channel 1 active: 0 ssrc: 0 Sep 13 23:39:42.656 [INFO ] MEDIA: StopCall: active channels: 1 Sep 13 23:39:42.656 [DEBUG0] SIP: SipIcmpDataCb: local/remote=Icmp:0.0.0.0:51803/Icmp:192.168.170.2:10035 Sep 13 23:39:42.657 [INFO ] MEDIA: StopCall: channel 0 active: 1 ssrc: 654321 Sep 13 23:39:42.657 [INFO ] MEDIA: StopCall: channel 1 active: 0 ssrc: 0 Sep 13 23:39:42.657 [DEBUG0] MEDIA: StreamClose: 2301071589 Sep 13 23:39:42.658 [DEBUG0] MEDIA: close stream 2301071589 with packet_ssrc 1297896780 Sep 13 23:39:42.658 [NOTICE] MEDIA: onRtpClose: RP116 Sep 13 23:39:42.659 [DEBUG0] MEDIA: onRtpClose: name: RP116 ssrc: 2301071589 Sep 13 23:39:42.659 [INFO ] MEDIA: NumberOfSocketsWithSsrc: ssrc: 2301071589, sockets: 1 Sep 13 23:39:42.659 [INFO ] MEDIA: onRtpClose: Only one socket with ssrc 2301071589 found, call can be closed Sep 13 23:39:42.660 [ERROR ] MEDIA: StopCall: failed to stop 2301071589 Sep 13 23:39:42.660 [DEBUG0] MEDIA: Socket 0x28ace8/noname: state disconnected(7) Sep 13 23:39:42.660 [DEBUG0] MEDIA: Socket 0x28ace8/noname: state deleted(8) Sep 13 23:39:42.661 [NOTICE] MEDIA: onRtpClose: RC116 Sep 13 23:39:42.661 [DEBUG0] MEDIA: onRtpClose: name: RC116 ssrc: 0 Sep 13 23:39:42.662 [INFO ] MEDIA: NumberOfSocketsWithSsrc: ssrc: 0, sockets: 0 Sep 13 23:39:42.663 [DEBUG0] MEDIA: Socket 0x28afd8/noname: state disconnected(7) Sep 13 23:39:42.663 [DEBUG0] MEDIA: Socket 0x28afd8/noname: state deleted(8) Sep 13 23:39:44.202 [INFO ] PHN: entering gui_object::display_on_minibrowser() state=4, force_redraw=0 Sep 13 23:39:44.203 [NOTICE] PHN: Fetching URL: phone://mb_exit Sep 13 23:39:44.205 [DEBUG1] PHN: Goto State 'Terminated' (12) from' Minibrowser_Message' (25), MB 0, blocked 0 caller:key_on_minibrowser_msg-56 Sep 13 23:39:44.206 [INFO ] PHN: Deleting channel 91, identity 1, state closed, total connection count 1 Sep 13 23:39:44.235 [DEBUG0] UXM: Request backlight for module -1 with value 15 Sep 13 23:39:44.235 [DEBUG1] PHN: Goto Best State from 'pTerminated' (12), force 1 called-by InitiateEndOfStateTerminated-99 Sep 13 23:39:44.236 [DEBUG1] PHN: Goto State 'Idle' (26) from' Terminated' (12), MB 0, blocked 0 caller:goto_best_state-608 Sep 13 23:39:44.252 [DEBUG0] UXM: Request backlight for module -1 with value 15 Sep 13 23:39:44.253 [DEBUG0] PHN: conference off TodosWhenPhoneTurnsIdle Sep 13 23:39:44.253 [DEBUG0] MEDIA: MediaIpc::setSpeakerDefault: 6 0 Sep 13 23:39:44.771 [DEBUG1] SIP: remove receive packet: 20573, all 8 Sep 13 23:39:45.636 [NOTICE] PHN: TPL: Socket 95 idle/connect timeout Sep 13 23:39:45.637 [DEBUG1] TLS: 0x1946bb0 SSL Alert write/0:warning:close notify Sep 13 23:39:45.986 [INFO ] PHN: LLDP: Skipped packet (420 bytes), not from router/bridge