2016-06-03 14:13:06,696 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319880 2016-06-03 14:13:06,697 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_inc_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:06,698 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_inc_timeout -> 0x2319808 2016-06-03 14:13:06,749 [INFO] [doorpi.sipphone.from_linphone] sound/wall clock skew is average=21,609236 ms 2016-06-03 14:13:06,750 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:06,751 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319880 2016-06-03 14:13:06,752 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_inc_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:06,753 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_inc_timeout -> 0x2319808 2016-06-03 14:13:06,804 [INFO] [doorpi.sipphone.from_linphone] Sending RTCP SR compound message on session [0x73c2dca0]. 2016-06-03 14:13:06,805 [INFO] [doorpi.sipphone.from_linphone] MSAudio_stream_iterate[0x73c2d2c8], local statistics available: Local current jitter buffer size: 60,0ms 2016-06-03 14:13:06,806 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_callback_call_stats_updated(0x24b0270, 0x73c2ecd8, 0x73c2f198) 2016-06-03 14:13:06,806 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_callback_call_stats_updated 2016-06-03 14:13:06,807 [INFO] [doorpi.sipphone.from_linphone] Linphone core [0x24b0270] notifying [call_stats_updated] 2016-06-03 14:13:06,808 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:06,809 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319880 2016-06-03 14:13:06,810 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_inc_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:06,811 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_inc_timeout -> 0x2319808 2016-06-03 14:13:06,862 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:06,863 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319880 2016-06-03 14:13:06,864 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_inc_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:06,864 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_inc_timeout -> 0x2319808 2016-06-03 14:13:06,916 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:06,917 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319880 2016-06-03 14:13:06,918 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_inc_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:06,918 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_inc_timeout -> 0x2319808 2016-06-03 14:13:06,970 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:06,971 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319880 2016-06-03 14:13:06,972 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_inc_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:06,973 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_inc_timeout -> 0x2319808 2016-06-03 14:13:07,024 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:07,025 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319880 2016-06-03 14:13:07,026 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_inc_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:07,027 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_inc_timeout -> 0x2319808 2016-06-03 14:13:07,078 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:07,079 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319880 2016-06-03 14:13:07,080 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_inc_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:07,081 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_inc_timeout -> 0x2319808 2016-06-03 14:13:07,132 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:07,134 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319880 2016-06-03 14:13:07,135 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_inc_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:07,135 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_inc_timeout -> 0x2319808 2016-06-03 14:13:07,187 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:07,188 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319880 2016-06-03 14:13:07,189 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_inc_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:07,189 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_inc_timeout -> 0x2319808 2016-06-03 14:13:07,241 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:07,241 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319880 2016-06-03 14:13:07,242 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_inc_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:07,243 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_inc_timeout -> 0x2319808 2016-06-03 14:13:07,296 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:07,297 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319880 2016-06-03 14:13:07,298 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_inc_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:07,299 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_inc_timeout -> 0x2319808 2016-06-03 14:13:07,351 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:07,352 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319880 2016-06-03 14:13:07,353 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_inc_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:07,353 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_inc_timeout -> 0x2319808 2016-06-03 14:13:07,405 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:07,406 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319880 2016-06-03 14:13:07,407 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_inc_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:07,407 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_inc_timeout -> 0x2319808 2016-06-03 14:13:07,459 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:07,460 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319880 2016-06-03 14:13:07,461 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_inc_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:07,462 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_inc_timeout -> 0x2319808 2016-06-03 14:13:07,513 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_callback_call_stats_updated(0x24b0270, 0x73c2ecd8, 0x73c2f198) 2016-06-03 14:13:07,514 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_callback_call_stats_updated 2016-06-03 14:13:07,514 [INFO] [doorpi.sipphone.from_linphone] Linphone core [0x24b0270] notifying [call_stats_updated] 2016-06-03 14:13:07,515 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_callback_call_stats_updated(0x24b0270, 0x73c2ecd8, 0x73c2f250) 2016-06-03 14:13:07,516 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_callback_call_stats_updated 2016-06-03 14:13:07,516 [INFO] [doorpi.sipphone.from_linphone] Linphone core [0x24b0270] notifying [call_stats_updated] 2016-06-03 14:13:07,517 [INFO] [doorpi.sipphone.from_linphone] Bandwidth usage for call [0x73c2ecd8]: RTP audio=[d= 80,9,u= 79,3], video=[d= 0,0,u= 0,0] kbits/sec RTCP audio=[d= 0,0,u= 1,0], video=[d= 0,0,u= 0,0] kbits/sec 2016-06-03 14:13:07,518 [INFO] [doorpi.sipphone.from_linphone] Thread processing load: audio=13,190553 video=0,000000 2016-06-03 14:13:07,519 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:07,520 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319880 2016-06-03 14:13:07,521 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_inc_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:07,521 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_inc_timeout -> 0x2319808 2016-06-03 14:13:07,573 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:07,573 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319880 2016-06-03 14:13:07,574 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_inc_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:07,575 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_inc_timeout -> 0x2319808 2016-06-03 14:13:07,627 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:07,628 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319880 2016-06-03 14:13:07,628 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_inc_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:07,629 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_inc_timeout -> 0x2319808 2016-06-03 14:13:07,680 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:07,681 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319880 2016-06-03 14:13:07,682 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_inc_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:07,683 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_inc_timeout -> 0x2319808 2016-06-03 14:13:07,734 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:07,735 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319880 2016-06-03 14:13:07,736 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_inc_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:07,737 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_inc_timeout -> 0x2319808 2016-06-03 14:13:07,788 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:07,789 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319880 2016-06-03 14:13:07,790 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_inc_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:07,791 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_inc_timeout -> 0x2319808 2016-06-03 14:13:07,842 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:07,843 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319880 2016-06-03 14:13:07,844 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_inc_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:07,845 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_inc_timeout -> 0x2319808 2016-06-03 14:13:07,898 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:07,898 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319880 2016-06-03 14:13:07,899 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_inc_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:07,900 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_inc_timeout -> 0x2319808 2016-06-03 14:13:07,951 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:07,952 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319880 2016-06-03 14:13:07,954 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_inc_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:07,954 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_inc_timeout -> 0x2319808 2016-06-03 14:13:08,006 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:08,007 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319880 2016-06-03 14:13:08,008 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_inc_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:08,008 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_inc_timeout -> 0x2319808 2016-06-03 14:13:08,060 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:08,061 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319880 2016-06-03 14:13:08,062 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_inc_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:08,062 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_inc_timeout -> 0x2319808 2016-06-03 14:13:08,114 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8]: received [895] new bytes from [UDP://192.168.16.1:5060]: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.16.121:5060;branch=z9hG4bK.RJ9BFBcJr;rport=5060 From: "DoorPi" ;tag=IJY0rZFYP To: ;tag=5FEADD4AF6C8C769 Call-ID: IxDsspm96- CSeq: 21 INVITE Contact: User-Agent: AVM FRITZ!Box 7490 113.06.51 (Feb 3 2016) Supported: 100rel,replaces,timer Allow-Events: telephone-event,refer Allow: INVITE,ACK,OPTIONS,CANCEL,BYE,UPDATE,PRACK,INFO,SUBSCRIBE,NOTIFY,REFER,MESSAGE,PUBLISH Content-Type: application/sdp Accept: application/sdp, multipart/mixed Accept-Encoding: identity Content-Length: 260 v=0 o=user 5629004 5629004 IN IP4 192.168.16.1 s=Talk c=IN IP4 192.168.16.1 t=0 0 m=audio 7098 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv a=rtcp:7099 m=video 0 RTP/AVP 96 2016-06-03 14:13:08,128 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8] [635] bytes parsed 2016-06-03 14:13:08,129 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8] read [260] bytes of body from [192.168.16.1:5060] 2016-06-03 14:13:08,130 [INFO] [doorpi.sipphone.from_linphone] Found transaction matching response. 2016-06-03 14:13:08,131 [INFO] [doorpi.sipphone.from_linphone] Changing [client] [INVITE] transaction [0x24d1648], from state [PROCEEDING] to [ACCEPTED] 2016-06-03 14:13:08,132 [INFO] [doorpi.sipphone.from_linphone] Dialog [0x24dec30]: now updated by transaction [0x24d1648]. 2016-06-03 14:13:08,136 [INFO] [doorpi.sipphone.from_linphone] op [0x73c2d200] : set_or_update_dialog() current=[0x24dec30] new=[0x24dec30] 2016-06-03 14:13:08,137 [INFO] [doorpi.sipphone.from_linphone] Op [0x73c2d200] receiving call response [200], dialog is [0x24dec30] in state [BELLE_SIP_DIALOG_CONFIRMED] 2016-06-03 14:13:08,142 [INFO] [doorpi.sipphone.from_linphone] Found payload PCMU/8000 fmtp= 2016-06-03 14:13:08,143 [INFO] [doorpi.sipphone.from_linphone] Found payload PCMA/8000 fmtp= 2016-06-03 14:13:08,143 [INFO] [doorpi.sipphone.from_linphone] Found payload telephone-event/8000 fmtp=0-15 2016-06-03 14:13:08,144 [INFO] [doorpi.sipphone.from_linphone] Found payload (null)/0 fmtp= 2016-06-03 14:13:08,145 [INFO] [doorpi.sipphone.from_linphone] Doing SDP offer/answer process of type outgoing 2016-06-03 14:13:08,146 [INFO] [doorpi.sipphone.from_linphone] Processing for stream 0 2016-06-03 14:13:08,146 [INFO] [doorpi.sipphone.from_linphone] Processing for stream 1 2016-06-03 14:13:08,147 [INFO] [doorpi.sipphone.from_linphone] Local stream description [0x73c064e8] rejected by peer 2016-06-03 14:13:08,148 [INFO] [doorpi.sipphone.from_linphone] Computing branch id z9hG4bK.hHOps7yZ2 for message sent statelessly 2016-06-03 14:13:08,149 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8]: message sent to [UDP://192.168.16.1:5060], size: [442] bytes ACK sip:BB1F600A341C3CC4537D5984D93A1@192.168.16.1 SIP/2.0 Via: SIP/2.0/UDP 192.168.16.121:5060;rport;branch=z9hG4bK.hHOps7yZ2 From: "DoorPi" ;tag=IJY0rZFYP To: ;tag=5FEADD4AF6C8C769 CSeq: 21 ACK Call-ID: IxDsspm96- Max-Forwards: 70 Authorization: Digest realm="fritz.box", nonce="934786E3361ACD2D", username="624", uri="sip:11@192.168.16.1", response="0de4212cdcbce75008bd3d0976439e94" 2016-06-03 14:13:08,150 [INFO] [doorpi.sipphone.from_linphone] Call 0x73c2ecd8: moving from state LinphoneCallOutgoingEarlyMedia to LinphoneCallConnected 2016-06-03 14:13:08,151 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_callback_call_state_changed(0x24b0270, 0x73c2ecd8, 6, "Connected") 2016-06-03 14:13:08,152 [DEBUG] [doorpi.sipphone.linphone_lib.CallBacks] call_state_changed (6 - Connected) 2016-06-03 14:13:08,152 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_remote_address(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:08,153 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Address_from_native_ptr(0x73c03658) 2016-06-03 14:13:08,154 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Address_new() 2016-06-03 14:13:08,154 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Address_new -> 0x76cd7590 2016-06-03 14:13:08,155 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Address_init() 2016-06-03 14:13:08,156 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Address_init -> 0x76cd7590 2016-06-03 14:13:08,156 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Address_from_native_ptr -> 0x76cd7590 2016-06-03 14:13:08,157 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_remote_address -> 0x76cd7590 2016-06-03 14:13:08,158 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Address_instance_method_as_string_uri_only(0x76cd7590 [0x73c03658]) 2016-06-03 14:13:08,158 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Address_instance_method_as_string_uri_only -> 0x72f470e8 2016-06-03 14:13:08,159 [TRACE] [doorpi.action.handler] fire Event OnCallStateChange from doorpi.sipphone.linphone_lib.CallBacks asyncron 2016-06-03 14:13:08,161 [TRACE] [doorpi.action.handler] fire Event OnCallStateConnect from doorpi.sipphone.linphone_lib.CallBacks asyncron 2016-06-03 14:13:08,163 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_calls_nb(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:08,164 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_calls_nb -> 0x23198b0 2016-06-03 14:13:08,164 [DEBUG] [doorpi.action.handler] no actions for event OnCallStateChange - skip fire_event OnCallStateChange from doorpi.sipphone.linphone_lib.CallBacks 2016-06-03 14:13:08,165 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_calls_nb(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:08,166 [DEBUG] [doorpi.action.handler] [JL72NE] fire for event OnCallStateConnect this actions [, ] 2016-06-03 14:13:08,167 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_calls_nb -> 0x23198b0 2016-06-03 14:13:08,168 [TRACE] [doorpi.action.handler] [JL72NE] try to fire action > with args () and kwargs {} 2016-06-03 14:13:08,169 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_calls_nb(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:08,169 [TRACE] [doorpi.action.base] run SingleAction with args () and kwargs {} 2016-06-03 14:13:08,170 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_calls_nb -> 0x23198b0 2016-06-03 14:13:08,171 [TRACE] [doorpi.action.handler] fire Event OnPlayerStopped from doorpi.sipphone.linphone_lib.Player asyncron 2016-06-03 14:13:08,172 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_callback_call_state_changed 2016-06-03 14:13:08,173 [INFO] [doorpi.sipphone.from_linphone] Linphone core [0x24b0270] notifying [call_state_changed] 2016-06-03 14:13:08,175 [INFO] [doorpi.sipphone.from_linphone] Early media finished, unmuting inputs... 2016-06-03 14:13:08,176 [INFO] [doorpi.sipphone.from_linphone] MSVolume set gain to [0,000000 db], [1,000000] linear 2016-06-03 14:13:08,177 [INFO] [doorpi.sipphone.from_linphone] No need to restart streams, SDP is unchanged. 2016-06-03 14:13:08,178 [INFO] [doorpi.sipphone.from_linphone] audio stream index found: 0, updating main audio stream index 2016-06-03 14:13:08,179 [INFO] [doorpi.sipphone.from_linphone] video stream index found: 1, updating main video stream index 2016-06-03 14:13:08,180 [INFO] [doorpi.sipphone.from_linphone] Call [0x73c2ecd8]: disabling video in our call params because the remote doesn't want it. 2016-06-03 14:13:08,180 [TRACE] [doorpi.action.handler] [JL72NE] try to fire action > with args () and kwargs {} 2016-06-03 14:13:08,181 [INFO] [doorpi.sipphone.from_linphone] Call 0x73c2ecd8: moving from state LinphoneCallConnected to LinphoneCallStreamsRunning 2016-06-03 14:13:08,181 [DEBUG] [doorpi.action.handler] no actions for event OnPlayerStopped - skip fire_event OnPlayerStopped from doorpi.sipphone.linphone_lib.Player 2016-06-03 14:13:08,182 [TRACE] [doorpi.action.base] run SingleAction with args () and kwargs {} 2016-06-03 14:13:08,182 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_callback_call_state_changed(0x24b0270, 0x73c2ecd8, 7, "Streams running") 2016-06-03 14:13:08,187 [DEBUG] [doorpi.sipphone.linphone_lib.CallBacks] call_state_changed (7 - Streams running) 2016-06-03 14:13:08,187 [DEBUG] [doorpi.sipphone.linphone_lib.Recorder] starting recording to /usr/local/etc/DoorPi/records/2016-06-03_14-13-08.wav 2016-06-03 14:13:08,188 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_remote_address(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:08,189 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_instance_method_start_recording(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:08,190 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Address_from_native_ptr(0x73c03658) 2016-06-03 14:13:08,190 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_instance_method_start_recording -> None 2016-06-03 14:13:08,191 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Address_new() 2016-06-03 14:13:08,192 [TRACE] [doorpi.action.handler] fire Event OnRecorderStarted from doorpi.sipphone.linphone_lib.Recorder asyncron 2016-06-03 14:13:08,193 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Address_new -> 0x76cd75a0 2016-06-03 14:13:08,194 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Address_init() 2016-06-03 14:13:08,196 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Address_init -> 0x76cd75a0 2016-06-03 14:13:08,197 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Address_from_native_ptr -> 0x76cd75a0 2016-06-03 14:13:08,197 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_remote_address -> 0x76cd75a0 2016-06-03 14:13:08,198 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Address_instance_method_as_string_uri_only(0x76cd75a0 [0x73c03658]) 2016-06-03 14:13:08,199 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Address_instance_method_as_string_uri_only -> 0x745d2750 2016-06-03 14:13:08,199 [TRACE] [doorpi.action.handler] fire Event OnCallStateChange from doorpi.sipphone.linphone_lib.CallBacks asyncron 2016-06-03 14:13:08,201 [TRACE] [doorpi.action.handler] [JL72NE] finished fire_event for event_name OnCallStateConnect 2016-06-03 14:13:08,201 [DEBUG] [doorpi.action.handler] no actions for event OnRecorderStarted - skip fire_event OnRecorderStarted from doorpi.sipphone.linphone_lib.Recorder 2016-06-03 14:13:08,203 [TRACE] [doorpi.action.handler] fire Event AfterCallStateConnect from doorpi.sipphone.linphone_lib.CallBacks asyncron 2016-06-03 14:13:08,206 [TRACE] [doorpi.action.handler] fire Event OnCallMediaStateChange from doorpi.sipphone.linphone_lib.CallBacks asyncron 2016-06-03 14:13:08,207 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_calls_nb(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:08,208 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_calls_nb -> 0x23198b0 2016-06-03 14:13:08,208 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_calls_nb(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:08,208 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_calls_nb -> 0x23198b0 2016-06-03 14:13:08,209 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_calls_nb(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:08,209 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_calls_nb -> 0x23198b0 2016-06-03 14:13:08,209 [DEBUG] [doorpi.action.handler] no actions for event OnCallStateChange - skip fire_event OnCallStateChange from doorpi.sipphone.linphone_lib.CallBacks 2016-06-03 14:13:08,210 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_callback_call_state_changed 2016-06-03 14:13:08,210 [DEBUG] [doorpi.action.handler] no actions for event OnCallMediaStateChange - skip fire_event OnCallMediaStateChange from doorpi.sipphone.linphone_lib.CallBacks 2016-06-03 14:13:08,210 [DEBUG] [doorpi.action.handler] no actions for event AfterCallStateConnect - skip fire_event AfterCallStateConnect from doorpi.sipphone.linphone_lib.CallBacks 2016-06-03 14:13:08,211 [INFO] [doorpi.sipphone.from_linphone] MSFileRec: recording into /usr/local/etc/DoorPi/records/2016-06-03_14-12-59.wav 2016-06-03 14:13:08,212 [INFO] [doorpi.sipphone.from_linphone] MSAudioMixer [0x251ce98] is entering bypass mode. 2016-06-03 14:13:08,213 [INFO] [doorpi.sipphone.from_linphone] MSAudioMixer [0x251ce98] is leaving bypass mode. 2016-06-03 14:13:08,213 [INFO] [doorpi.sipphone.from_linphone] Linphone core [0x24b0270] notifying [call_state_changed] 2016-06-03 14:13:08,213 [INFO] [doorpi.sipphone.from_linphone] Garbage collecting unowned object of type belle_sip_hop_t 2016-06-03 14:13:08,214 [INFO] [doorpi.sipphone.from_linphone] Garbage collecting unowned object of type belle_sdp_session_description_t 2016-06-03 14:13:08,214 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:08,215 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:08,215 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:08,215 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:08,266 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8]: received [532] new bytes from [UDP://192.168.16.1:5060]: INFO sip:624@192.168.16.121 SIP/2.0 Via: SIP/2.0/UDP 192.168.16.1:5060;branch=z9hG4bK048E6966C0375EB2 From: ;tag=5FEADD4AF6C8C769 To: "DoorPi" ;tag=IJY0rZFYP Call-ID: IxDsspm96- CSeq: 22 INFO Contact: Max-Forwards: 70 User-Agent: AVM FRITZ!Box 7490 113.06.51 (Feb 3 2016) Supported: 100rel,replaces,timer Allow-Events: telephone-event,refer Content-Type: application/dtmf-relay Content-Length: 24 Signal=# Duration=100 2016-06-03 14:13:08,274 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8] [508] bytes parsed 2016-06-03 14:13:08,274 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8] read [24] bytes of body from [192.168.16.1:5060] 2016-06-03 14:13:08,277 [INFO] [doorpi.sipphone.from_linphone] Changing [server] [INFO] transaction [0x251fd18], from state [INIT] to [TRYING] 2016-06-03 14:13:08,278 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_callback_dtmf_received(0x24b0270, 0x73c2ecd8, 35) 2016-06-03 14:13:08,278 [DEBUG] [doorpi.sipphone.linphone_lib.CallBacks] on_dtmf_digit (35) 2016-06-03 14:13:08,279 [TRACE] [doorpi.action.handler] fire Event OnDTMF from doorpi.sipphone.linphone_lib.CallBacks asyncron 2016-06-03 14:13:08,280 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_callback_dtmf_received 2016-06-03 14:13:08,280 [INFO] [doorpi.sipphone.from_linphone] Linphone core [0x24b0270] notifying [dtmf_received] 2016-06-03 14:13:08,280 [DEBUG] [doorpi.action.handler] no actions for event OnDTMF - skip fire_event OnDTMF from doorpi.sipphone.linphone_lib.CallBacks 2016-06-03 14:13:08,281 [INFO] [doorpi.sipphone.from_linphone] Changing [server] [INFO] transaction [0x251fd18], from state [TRYING] to [COMPLETED] 2016-06-03 14:13:08,282 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8]: message sent to [UDP://192.168.16.1:5060], size: [274] bytes SIP/2.0 200 Ok Via: SIP/2.0/UDP 192.168.16.1:5060;branch=z9hG4bK048E6966C0375EB2 From: ;tag=5FEADD4AF6C8C769 To: "DoorPi" ;tag=IJY0rZFYP Call-ID: IxDsspm96- CSeq: 22 INFO User-Agent: (belle-sip/1.4.2) Supported: outbound 2016-06-03 14:13:08,283 [INFO] [doorpi.sipphone.from_linphone] Dialog [0x24dec30]: now updated by transaction [0x251fd18]. 2016-06-03 14:13:08,283 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:08,284 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:08,284 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:08,284 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:08,335 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8]: received [532] new bytes from [UDP://192.168.16.1:5060]: INFO sip:624@192.168.16.121 SIP/2.0 Via: SIP/2.0/UDP 192.168.16.1:5060;branch=z9hG4bK85A6371445B0B7B6 From: ;tag=5FEADD4AF6C8C769 To: "DoorPi" ;tag=IJY0rZFYP Call-ID: IxDsspm96- CSeq: 23 INFO Contact: Max-Forwards: 70 User-Agent: AVM FRITZ!Box 7490 113.06.51 (Feb 3 2016) Supported: 100rel,replaces,timer Allow-Events: telephone-event,refer Content-Type: application/dtmf-relay Content-Length: 24 Signal=1 Duration=100 2016-06-03 14:13:08,343 [INFO] [doorpi.sipphone.from_linphone] sound/wall clock skew is average=27,742980 ms 2016-06-03 14:13:08,343 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8] [508] bytes parsed 2016-06-03 14:13:08,343 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8] read [24] bytes of body from [192.168.16.1:5060] 2016-06-03 14:13:08,345 [INFO] [doorpi.sipphone.from_linphone] Changing [server] [INFO] transaction [0x2535100], from state [INIT] to [TRYING] 2016-06-03 14:13:08,346 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_callback_dtmf_received(0x24b0270, 0x73c2ecd8, 49) 2016-06-03 14:13:08,346 [DEBUG] [doorpi.sipphone.linphone_lib.CallBacks] on_dtmf_digit (49) 2016-06-03 14:13:08,347 [TRACE] [doorpi.action.handler] fire Event OnDTMF from doorpi.sipphone.linphone_lib.CallBacks asyncron 2016-06-03 14:13:08,348 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_callback_dtmf_received 2016-06-03 14:13:08,348 [INFO] [doorpi.sipphone.from_linphone] Linphone core [0x24b0270] notifying [dtmf_received] 2016-06-03 14:13:08,348 [INFO] [doorpi.sipphone.from_linphone] Changing [server] [INFO] transaction [0x2535100], from state [TRYING] to [COMPLETED] 2016-06-03 14:13:08,349 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8]: message sent to [UDP://192.168.16.1:5060], size: [274] bytes SIP/2.0 200 Ok Via: SIP/2.0/UDP 192.168.16.1:5060;branch=z9hG4bK85A6371445B0B7B6 From: ;tag=5FEADD4AF6C8C769 To: "DoorPi" ;tag=IJY0rZFYP Call-ID: IxDsspm96- CSeq: 23 INFO User-Agent: (belle-sip/1.4.2) Supported: outbound 2016-06-03 14:13:08,349 [INFO] [doorpi.sipphone.from_linphone] Dialog [0x24dec30]: now updated by transaction [0x2535100]. 2016-06-03 14:13:08,350 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:08,350 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:08,351 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:08,351 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:08,352 [DEBUG] [doorpi.action.handler] no actions for event OnDTMF - skip fire_event OnDTMF from doorpi.sipphone.linphone_lib.CallBacks 2016-06-03 14:13:08,402 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:08,402 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:08,403 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:08,403 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:08,454 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:08,455 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:08,455 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:08,456 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:08,506 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8]: received [532] new bytes from [UDP://192.168.16.1:5060]: INFO sip:624@192.168.16.121 SIP/2.0 Via: SIP/2.0/UDP 192.168.16.1:5060;branch=z9hG4bKA2B19820D1249BBB From: ;tag=5FEADD4AF6C8C769 To: "DoorPi" ;tag=IJY0rZFYP Call-ID: IxDsspm96- CSeq: 24 INFO Contact: Max-Forwards: 70 User-Agent: AVM FRITZ!Box 7490 113.06.51 (Feb 3 2016) Supported: 100rel,replaces,timer Allow-Events: telephone-event,refer Content-Type: application/dtmf-relay Content-Length: 24 Signal=2 Duration=100 2016-06-03 14:13:08,514 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8] [508] bytes parsed 2016-06-03 14:13:08,514 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8] read [24] bytes of body from [192.168.16.1:5060] 2016-06-03 14:13:08,516 [INFO] [doorpi.sipphone.from_linphone] Changing [server] [INFO] transaction [0x2580ea8], from state [INIT] to [TRYING] 2016-06-03 14:13:08,517 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_callback_dtmf_received(0x24b0270, 0x73c2ecd8, 50) 2016-06-03 14:13:08,517 [DEBUG] [doorpi.sipphone.linphone_lib.CallBacks] on_dtmf_digit (50) 2016-06-03 14:13:08,517 [TRACE] [doorpi.action.handler] fire Event OnDTMF from doorpi.sipphone.linphone_lib.CallBacks asyncron 2016-06-03 14:13:08,518 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_callback_dtmf_received 2016-06-03 14:13:08,519 [INFO] [doorpi.sipphone.from_linphone] Linphone core [0x24b0270] notifying [dtmf_received] 2016-06-03 14:13:08,519 [DEBUG] [doorpi.action.handler] no actions for event OnDTMF - skip fire_event OnDTMF from doorpi.sipphone.linphone_lib.CallBacks 2016-06-03 14:13:08,520 [INFO] [doorpi.sipphone.from_linphone] Changing [server] [INFO] transaction [0x2580ea8], from state [TRYING] to [COMPLETED] 2016-06-03 14:13:08,521 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8]: message sent to [UDP://192.168.16.1:5060], size: [274] bytes SIP/2.0 200 Ok Via: SIP/2.0/UDP 192.168.16.1:5060;branch=z9hG4bKA2B19820D1249BBB From: ;tag=5FEADD4AF6C8C769 To: "DoorPi" ;tag=IJY0rZFYP Call-ID: IxDsspm96- CSeq: 24 INFO User-Agent: (belle-sip/1.4.2) Supported: outbound 2016-06-03 14:13:08,521 [INFO] [doorpi.sipphone.from_linphone] Dialog [0x24dec30]: now updated by transaction [0x2580ea8]. 2016-06-03 14:13:08,521 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_callback_call_stats_updated(0x24b0270, 0x73c2ecd8, 0x73c2f198) 2016-06-03 14:13:08,522 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_callback_call_stats_updated 2016-06-03 14:13:08,522 [INFO] [doorpi.sipphone.from_linphone] Linphone core [0x24b0270] notifying [call_stats_updated] 2016-06-03 14:13:08,522 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_callback_call_stats_updated(0x24b0270, 0x73c2ecd8, 0x73c2f250) 2016-06-03 14:13:08,523 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_callback_call_stats_updated 2016-06-03 14:13:08,523 [INFO] [doorpi.sipphone.from_linphone] Linphone core [0x24b0270] notifying [call_stats_updated] 2016-06-03 14:13:08,524 [INFO] [doorpi.sipphone.from_linphone] Bandwidth usage for call [0x73c2ecd8]: RTP audio=[d= 79,9,u= 79,9], video=[d= 0,0,u= 0,0] kbits/sec RTCP audio=[d= 0,0,u= 0,0], video=[d= 0,0,u= 0,0] kbits/sec 2016-06-03 14:13:08,524 [INFO] [doorpi.sipphone.from_linphone] Thread processing load: audio=12,139050 video=0,000000 2016-06-03 14:13:08,524 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:08,525 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:08,525 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:08,526 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:08,577 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:08,577 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:08,578 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:08,578 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:08,630 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:08,630 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:08,632 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:08,632 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:08,683 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8]: received [532] new bytes from [UDP://192.168.16.1:5060]: INFO sip:624@192.168.16.121 SIP/2.0 Via: SIP/2.0/UDP 192.168.16.1:5060;branch=z9hG4bK4FF739070468A6AE From: ;tag=5FEADD4AF6C8C769 To: "DoorPi" ;tag=IJY0rZFYP Call-ID: IxDsspm96- CSeq: 25 INFO Contact: Max-Forwards: 70 User-Agent: AVM FRITZ!Box 7490 113.06.51 (Feb 3 2016) Supported: 100rel,replaces,timer Allow-Events: telephone-event,refer Content-Type: application/dtmf-relay Content-Length: 24 Signal=3 Duration=100 2016-06-03 14:13:08,690 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8] [508] bytes parsed 2016-06-03 14:13:08,691 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8] read [24] bytes of body from [192.168.16.1:5060] 2016-06-03 14:13:08,693 [INFO] [doorpi.sipphone.from_linphone] Changing [server] [INFO] transaction [0x2517628], from state [INIT] to [TRYING] 2016-06-03 14:13:08,693 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_callback_dtmf_received(0x24b0270, 0x73c2ecd8, 51) 2016-06-03 14:13:08,693 [DEBUG] [doorpi.sipphone.linphone_lib.CallBacks] on_dtmf_digit (51) 2016-06-03 14:13:08,694 [TRACE] [doorpi.action.handler] fire Event OnDTMF from doorpi.sipphone.linphone_lib.CallBacks asyncron 2016-06-03 14:13:08,695 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_callback_dtmf_received 2016-06-03 14:13:08,695 [INFO] [doorpi.sipphone.from_linphone] Linphone core [0x24b0270] notifying [dtmf_received] 2016-06-03 14:13:08,696 [DEBUG] [doorpi.action.handler] no actions for event OnDTMF - skip fire_event OnDTMF from doorpi.sipphone.linphone_lib.CallBacks 2016-06-03 14:13:08,696 [INFO] [doorpi.sipphone.from_linphone] Changing [server] [INFO] transaction [0x2517628], from state [TRYING] to [COMPLETED] 2016-06-03 14:13:08,697 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8]: message sent to [UDP://192.168.16.1:5060], size: [274] bytes SIP/2.0 200 Ok Via: SIP/2.0/UDP 192.168.16.1:5060;branch=z9hG4bK4FF739070468A6AE From: ;tag=5FEADD4AF6C8C769 To: "DoorPi" ;tag=IJY0rZFYP Call-ID: IxDsspm96- CSeq: 25 INFO User-Agent: (belle-sip/1.4.2) Supported: outbound 2016-06-03 14:13:08,697 [INFO] [doorpi.sipphone.from_linphone] Dialog [0x24dec30]: now updated by transaction [0x2517628]. 2016-06-03 14:13:08,698 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:08,698 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:08,699 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:08,699 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:08,750 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:08,751 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:08,751 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:08,752 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:08,803 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:08,803 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:08,804 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:08,804 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:08,855 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8]: received [532] new bytes from [UDP://192.168.16.1:5060]: INFO sip:624@192.168.16.121 SIP/2.0 Via: SIP/2.0/UDP 192.168.16.1:5060;branch=z9hG4bK681B3AC05C7A7FFD From: ;tag=5FEADD4AF6C8C769 To: "DoorPi" ;tag=IJY0rZFYP Call-ID: IxDsspm96- CSeq: 26 INFO Contact: Max-Forwards: 70 User-Agent: AVM FRITZ!Box 7490 113.06.51 (Feb 3 2016) Supported: 100rel,replaces,timer Allow-Events: telephone-event,refer Content-Type: application/dtmf-relay Content-Length: 24 Signal=4 Duration=100 2016-06-03 14:13:08,862 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8] [508] bytes parsed 2016-06-03 14:13:08,863 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8] read [24] bytes of body from [192.168.16.1:5060] 2016-06-03 14:13:08,864 [INFO] [doorpi.sipphone.from_linphone] Changing [server] [INFO] transaction [0x2535e48], from state [INIT] to [TRYING] 2016-06-03 14:13:08,865 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_callback_dtmf_received(0x24b0270, 0x73c2ecd8, 52) 2016-06-03 14:13:08,866 [DEBUG] [doorpi.sipphone.linphone_lib.CallBacks] on_dtmf_digit (52) 2016-06-03 14:13:08,866 [TRACE] [doorpi.action.handler] fire Event OnDTMF from doorpi.sipphone.linphone_lib.CallBacks asyncron 2016-06-03 14:13:08,867 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_callback_dtmf_received 2016-06-03 14:13:08,868 [INFO] [doorpi.sipphone.from_linphone] Linphone core [0x24b0270] notifying [dtmf_received] 2016-06-03 14:13:08,868 [DEBUG] [doorpi.action.handler] no actions for event OnDTMF - skip fire_event OnDTMF from doorpi.sipphone.linphone_lib.CallBacks 2016-06-03 14:13:08,868 [INFO] [doorpi.sipphone.from_linphone] Changing [server] [INFO] transaction [0x2535e48], from state [TRYING] to [COMPLETED] 2016-06-03 14:13:08,869 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8]: message sent to [UDP://192.168.16.1:5060], size: [274] bytes SIP/2.0 200 Ok Via: SIP/2.0/UDP 192.168.16.1:5060;branch=z9hG4bK681B3AC05C7A7FFD From: ;tag=5FEADD4AF6C8C769 To: "DoorPi" ;tag=IJY0rZFYP Call-ID: IxDsspm96- CSeq: 26 INFO User-Agent: (belle-sip/1.4.2) Supported: outbound 2016-06-03 14:13:08,870 [INFO] [doorpi.sipphone.from_linphone] Dialog [0x24dec30]: now updated by transaction [0x2535e48]. 2016-06-03 14:13:08,871 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:08,871 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:08,872 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:08,872 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:08,923 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:08,924 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:08,925 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:08,926 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:08,977 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:08,978 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:08,979 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:08,980 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:09,031 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8]: received [532] new bytes from [UDP://192.168.16.1:5060]: INFO sip:624@192.168.16.121 SIP/2.0 Via: SIP/2.0/UDP 192.168.16.1:5060;branch=z9hG4bKA7405A3B49D35DB9 From: ;tag=5FEADD4AF6C8C769 To: "DoorPi" ;tag=IJY0rZFYP Call-ID: IxDsspm96- CSeq: 27 INFO Contact: Max-Forwards: 70 User-Agent: AVM FRITZ!Box 7490 113.06.51 (Feb 3 2016) Supported: 100rel,replaces,timer Allow-Events: telephone-event,refer Content-Type: application/dtmf-relay Content-Length: 24 Signal=5 Duration=100 2016-06-03 14:13:09,047 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8] [508] bytes parsed 2016-06-03 14:13:09,049 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8] read [24] bytes of body from [192.168.16.1:5060] 2016-06-03 14:13:09,053 [INFO] [doorpi.sipphone.from_linphone] Changing [server] [INFO] transaction [0x2580120], from state [INIT] to [TRYING] 2016-06-03 14:13:09,054 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_callback_dtmf_received(0x24b0270, 0x73c2ecd8, 53) 2016-06-03 14:13:09,055 [DEBUG] [doorpi.sipphone.linphone_lib.CallBacks] on_dtmf_digit (53) 2016-06-03 14:13:09,056 [TRACE] [doorpi.action.handler] fire Event OnDTMF from doorpi.sipphone.linphone_lib.CallBacks asyncron 2016-06-03 14:13:09,059 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_callback_dtmf_received 2016-06-03 14:13:09,060 [INFO] [doorpi.sipphone.from_linphone] Linphone core [0x24b0270] notifying [dtmf_received] 2016-06-03 14:13:09,061 [DEBUG] [doorpi.action.handler] no actions for event OnDTMF - skip fire_event OnDTMF from doorpi.sipphone.linphone_lib.CallBacks 2016-06-03 14:13:09,062 [INFO] [doorpi.sipphone.from_linphone] Changing [server] [INFO] transaction [0x2580120], from state [TRYING] to [COMPLETED] 2016-06-03 14:13:09,065 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8]: message sent to [UDP://192.168.16.1:5060], size: [274] bytes SIP/2.0 200 Ok Via: SIP/2.0/UDP 192.168.16.1:5060;branch=z9hG4bKA7405A3B49D35DB9 From: ;tag=5FEADD4AF6C8C769 To: "DoorPi" ;tag=IJY0rZFYP Call-ID: IxDsspm96- CSeq: 27 INFO User-Agent: (belle-sip/1.4.2) Supported: outbound 2016-06-03 14:13:09,071 [INFO] [doorpi.sipphone.from_linphone] Dialog [0x24dec30]: now updated by transaction [0x2580120]. 2016-06-03 14:13:09,074 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:09,076 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:09,078 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:09,081 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:09,134 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:09,137 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:09,140 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:09,142 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:09,195 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8]: received [532] new bytes from [UDP://192.168.16.1:5060]: INFO sip:624@192.168.16.121 SIP/2.0 Via: SIP/2.0/UDP 192.168.16.1:5060;branch=z9hG4bK2995C79EA5096589 From: ;tag=5FEADD4AF6C8C769 To: "DoorPi" ;tag=IJY0rZFYP Call-ID: IxDsspm96- CSeq: 28 INFO Contact: Max-Forwards: 70 User-Agent: AVM FRITZ!Box 7490 113.06.51 (Feb 3 2016) Supported: 100rel,replaces,timer Allow-Events: telephone-event,refer Content-Type: application/dtmf-relay Content-Length: 24 Signal=6 Duration=100 2016-06-03 14:13:09,215 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8] [508] bytes parsed 2016-06-03 14:13:09,218 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8] read [24] bytes of body from [192.168.16.1:5060] 2016-06-03 14:13:09,222 [INFO] [doorpi.sipphone.from_linphone] Changing [server] [INFO] transaction [0x259d308], from state [INIT] to [TRYING] 2016-06-03 14:13:09,224 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_callback_dtmf_received(0x24b0270, 0x73c2ecd8, 54) 2016-06-03 14:13:09,225 [DEBUG] [doorpi.sipphone.linphone_lib.CallBacks] on_dtmf_digit (54) 2016-06-03 14:13:09,226 [TRACE] [doorpi.action.handler] fire Event OnDTMF from doorpi.sipphone.linphone_lib.CallBacks asyncron 2016-06-03 14:13:09,228 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_callback_dtmf_received 2016-06-03 14:13:09,230 [INFO] [doorpi.sipphone.from_linphone] Linphone core [0x24b0270] notifying [dtmf_received] 2016-06-03 14:13:09,230 [DEBUG] [doorpi.action.handler] no actions for event OnDTMF - skip fire_event OnDTMF from doorpi.sipphone.linphone_lib.CallBacks 2016-06-03 14:13:09,231 [INFO] [doorpi.sipphone.from_linphone] Changing [server] [INFO] transaction [0x259d308], from state [TRYING] to [COMPLETED] 2016-06-03 14:13:09,234 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8]: message sent to [UDP://192.168.16.1:5060], size: [274] bytes SIP/2.0 200 Ok Via: SIP/2.0/UDP 192.168.16.1:5060;branch=z9hG4bK2995C79EA5096589 From: ;tag=5FEADD4AF6C8C769 To: "DoorPi" ;tag=IJY0rZFYP Call-ID: IxDsspm96- CSeq: 28 INFO User-Agent: (belle-sip/1.4.2) Supported: outbound 2016-06-03 14:13:09,239 [INFO] [doorpi.sipphone.from_linphone] Dialog [0x24dec30]: now updated by transaction [0x259d308]. 2016-06-03 14:13:09,242 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:09,244 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:09,246 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:09,247 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:09,299 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:09,301 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:09,302 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:09,303 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:09,357 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8]: received [532] new bytes from [UDP://192.168.16.1:5060]: INFO sip:624@192.168.16.121 SIP/2.0 Via: SIP/2.0/UDP 192.168.16.1:5060;branch=z9hG4bK31DE6EC597250199 From: ;tag=5FEADD4AF6C8C769 To: "DoorPi" ;tag=IJY0rZFYP Call-ID: IxDsspm96- CSeq: 29 INFO Contact: Max-Forwards: 70 User-Agent: AVM FRITZ!Box 7490 113.06.51 (Feb 3 2016) Supported: 100rel,replaces,timer Allow-Events: telephone-event,refer Content-Type: application/dtmf-relay Content-Length: 24 Signal=# Duration=100 2016-06-03 14:13:09,380 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8] [508] bytes parsed 2016-06-03 14:13:09,382 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8] read [24] bytes of body from [192.168.16.1:5060] 2016-06-03 14:13:09,388 [INFO] [doorpi.sipphone.from_linphone] Changing [server] [INFO] transaction [0x2584fd0], from state [INIT] to [TRYING] 2016-06-03 14:13:09,390 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_callback_dtmf_received(0x24b0270, 0x73c2ecd8, 35) 2016-06-03 14:13:09,393 [DEBUG] [doorpi.sipphone.linphone_lib.CallBacks] on_dtmf_digit (35) 2016-06-03 14:13:09,395 [TRACE] [doorpi.action.handler] fire Event OnDTMF from doorpi.sipphone.linphone_lib.CallBacks asyncron 2016-06-03 14:13:09,398 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_remote_address(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:09,399 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Address_from_native_ptr(0x73c03658) 2016-06-03 14:13:09,400 [DEBUG] [doorpi.action.handler] no actions for event OnDTMF - skip fire_event OnDTMF from doorpi.sipphone.linphone_lib.CallBacks 2016-06-03 14:13:09,402 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Address_new() 2016-06-03 14:13:09,407 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Address_new -> 0x76cd7580 2016-06-03 14:13:09,410 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Address_init() 2016-06-03 14:13:09,411 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Address_init -> 0x76cd7580 2016-06-03 14:13:09,413 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Address_from_native_ptr -> 0x76cd7580 2016-06-03 14:13:09,416 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_remote_address -> 0x76cd7580 2016-06-03 14:13:09,418 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Address_instance_method_as_string_uri_only(0x76cd7580 [0x73c03658]) 2016-06-03 14:13:09,420 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Address_instance_method_as_string_uri_only -> 0x72f47250 2016-06-03 14:13:09,422 [TRACE] [doorpi.action.handler] fire Event OnDTMF_"#123456#" from doorpi.sipphone.linphone_lib.CallBacks asyncron 2016-06-03 14:13:09,426 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_callback_dtmf_received 2016-06-03 14:13:09,427 [DEBUG] [doorpi.action.handler] [P8DXP3] fire for event OnDTMF_"#123456#" this actions [] 2016-06-03 14:13:09,428 [TRACE] [doorpi.action.handler] [P8DXP3] try to fire action UrlCallAction with args () and kwargs {'url': 'http://192.168.16.5/config/xmlapi/statechange.cgi?ise_id=2971&new_value=true'} 2016-06-03 14:13:09,429 [TRACE] [doorpi.action.base] run UrlCallAction with args () and kwargs {'url': 'http://192.168.16.5/config/xmlapi/statechange.cgi?ise_id=2971&new_value=true'} 2016-06-03 14:13:09,428 [INFO] [doorpi.sipphone.from_linphone] Linphone core [0x24b0270] notifying [dtmf_received] 2016-06-03 14:13:09,430 [TRACE] [doorpi.action.handler] [P8DXP3] finished fire_event for event_name OnDTMF_"#123456#" 2016-06-03 14:13:09,432 [INFO] [doorpi.sipphone.from_linphone] Changing [server] [INFO] transaction [0x2584fd0], from state [TRYING] to [COMPLETED] 2016-06-03 14:13:09,437 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8]: message sent to [UDP://192.168.16.1:5060], size: [274] bytes SIP/2.0 200 Ok Via: SIP/2.0/UDP 192.168.16.1:5060;branch=z9hG4bK31DE6EC597250199 From: ;tag=5FEADD4AF6C8C769 To: "DoorPi" ;tag=IJY0rZFYP Call-ID: IxDsspm96- CSeq: 29 INFO User-Agent: (belle-sip/1.4.2) Supported: outbound 2016-06-03 14:13:09,440 [INFO] [doorpi.sipphone.from_linphone] Dialog [0x24dec30]: now updated by transaction [0x2584fd0]. 2016-06-03 14:13:09,442 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:09,443 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:09,445 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:09,446 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:09,498 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_callback_call_stats_updated(0x24b0270, 0x73c2ecd8, 0x73c2f198) 2016-06-03 14:13:09,499 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_callback_call_stats_updated 2016-06-03 14:13:09,500 [INFO] [doorpi.sipphone.from_linphone] Linphone core [0x24b0270] notifying [call_stats_updated] 2016-06-03 14:13:09,501 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_callback_call_stats_updated(0x24b0270, 0x73c2ecd8, 0x73c2f250) 2016-06-03 14:13:09,502 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_callback_call_stats_updated 2016-06-03 14:13:09,503 [INFO] [doorpi.sipphone.from_linphone] Linphone core [0x24b0270] notifying [call_stats_updated] 2016-06-03 14:13:09,504 [INFO] [doorpi.sipphone.from_linphone] Bandwidth usage for call [0x73c2ecd8]: RTP audio=[d= 79,3,u= 77,7], video=[d= 0,0,u= 0,0] kbits/sec RTCP audio=[d= 0,0,u= 0,0], video=[d= 0,0,u= 0,0] kbits/sec 2016-06-03 14:13:09,505 [INFO] [doorpi.sipphone.from_linphone] Thread processing load: audio=23,367046 video=0,000000 2016-06-03 14:13:09,506 [INFO] [doorpi.sipphone.from_linphone] MSAudio stream [0x73c2d2c8]: receiving RTCP SR 2016-06-03 14:13:09,508 [INFO] [doorpi.sipphone.from_linphone] MSSimpleQosAnalyzer: lost_percentage=0,000000, int_jitter=9,000000 ms, rt_prop=0,013580 sec 2016-06-03 14:13:09,509 [INFO] [doorpi.sipphone.from_linphone] MSSimpleQosAnalyzer: everything is fine. 2016-06-03 14:13:09,510 [INFO] [doorpi.sipphone.from_linphone] MSBitrateController: current state is Init 2016-06-03 14:13:09,511 [INFO] [doorpi.sipphone.from_linphone] MSQualityIndicator[0x73c2b9c8][audio], remote statistics available: Loss rate : 0,0% Inter-arrival jitter: 0,9ms RT propagation : 1,4ms 2016-06-03 14:13:09,513 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_callback_call_stats_updated(0x24b0270, 0x73c2ecd8, 0x73c2f198) 2016-06-03 14:13:09,514 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_callback_call_stats_updated 2016-06-03 14:13:09,515 [INFO] [doorpi.sipphone.from_linphone] Linphone core [0x24b0270] notifying [call_stats_updated] 2016-06-03 14:13:09,517 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:09,518 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:09,519 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:09,520 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:09,572 [INFO] [doorpi.sipphone.from_linphone] Sending RTCP SR compound message on session [0x73c2dca0]. 2016-06-03 14:13:09,573 [INFO] [doorpi.sipphone.from_linphone] MSAudio_stream_iterate[0x73c2d2c8], local statistics available: Local current jitter buffer size: 59,9ms 2016-06-03 14:13:09,574 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_callback_call_stats_updated(0x24b0270, 0x73c2ecd8, 0x73c2f198) 2016-06-03 14:13:09,575 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_callback_call_stats_updated 2016-06-03 14:13:09,576 [INFO] [doorpi.sipphone.from_linphone] Linphone core [0x24b0270] notifying [call_stats_updated] 2016-06-03 14:13:09,578 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:09,579 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:09,580 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:09,581 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:09,633 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:09,634 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:09,636 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:09,637 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:09,689 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:09,690 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:09,691 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:09,692 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:09,744 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:09,745 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:09,746 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:09,747 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:09,799 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:09,801 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:09,802 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:09,803 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:09,854 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:09,856 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:09,857 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:09,858 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:09,910 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:09,912 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:09,913 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:09,914 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:09,966 [INFO] [doorpi.sipphone.from_linphone] sound/wall clock skew is average=33,632972 ms 2016-06-03 14:13:09,967 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:09,968 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:09,969 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:09,970 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:10,022 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:10,023 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:10,025 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:10,026 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:10,079 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:10,080 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:10,081 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:10,082 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:10,134 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:10,135 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:10,136 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:10,137 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:10,188 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:10,189 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:10,190 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:10,191 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:10,242 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:10,244 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:10,245 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:10,246 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:10,299 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:10,300 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:10,301 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:10,303 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:10,355 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:10,356 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:10,358 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:10,359 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:10,411 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:10,412 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:10,413 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:10,413 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:10,466 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:10,466 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:10,467 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:10,468 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:10,519 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_callback_call_stats_updated(0x24b0270, 0x73c2ecd8, 0x73c2f198) 2016-06-03 14:13:10,520 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_callback_call_stats_updated 2016-06-03 14:13:10,521 [INFO] [doorpi.sipphone.from_linphone] Linphone core [0x24b0270] notifying [call_stats_updated] 2016-06-03 14:13:10,521 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_callback_call_stats_updated(0x24b0270, 0x73c2ecd8, 0x73c2f250) 2016-06-03 14:13:10,522 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_callback_call_stats_updated 2016-06-03 14:13:10,522 [INFO] [doorpi.sipphone.from_linphone] Linphone core [0x24b0270] notifying [call_stats_updated] 2016-06-03 14:13:10,523 [INFO] [doorpi.sipphone.from_linphone] Bandwidth usage for call [0x73c2ecd8]: RTP audio=[d= 80,0,u= 81,6], video=[d= 0,0,u= 0,0] kbits/sec RTCP audio=[d= 1,2,u= 1,0], video=[d= 0,0,u= 0,0] kbits/sec 2016-06-03 14:13:10,524 [INFO] [doorpi.sipphone.from_linphone] Thread processing load: audio=22,085539 video=0,000000 2016-06-03 14:13:10,525 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:10,526 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:10,527 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:10,527 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:10,579 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:10,580 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:10,581 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:10,582 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:10,634 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:10,634 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:10,635 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:10,636 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:10,688 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:10,689 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:10,690 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:10,691 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:10,742 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:10,743 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:10,744 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:10,745 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:10,797 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:10,797 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:10,798 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:10,800 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:10,851 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:10,852 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:10,853 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:10,854 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:10,906 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:10,906 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:10,908 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:10,908 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:10,960 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:10,961 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:10,962 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:10,962 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:11,014 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:11,015 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:11,016 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:11,017 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:11,068 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:11,069 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:11,070 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:11,071 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:11,123 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:11,124 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:11,126 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:11,127 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:11,179 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:11,180 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:11,182 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:11,183 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:11,235 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:11,236 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:11,238 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:11,239 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:11,293 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:11,295 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:11,296 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:11,297 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:11,350 [INFO] [doorpi.sipphone.from_linphone] Sending RTCP SR compound message on session [0x73c2dca0]. 2016-06-03 14:13:11,351 [INFO] [doorpi.sipphone.from_linphone] MSAudio_stream_iterate[0x73c2d2c8], local statistics available: Local current jitter buffer size: 60,0ms 2016-06-03 14:13:11,353 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_callback_call_stats_updated(0x24b0270, 0x73c2ecd8, 0x73c2f198) 2016-06-03 14:13:11,354 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_callback_call_stats_updated 2016-06-03 14:13:11,355 [INFO] [doorpi.sipphone.from_linphone] Linphone core [0x24b0270] notifying [call_stats_updated] 2016-06-03 14:13:11,357 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:11,358 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:11,360 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:11,361 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:11,414 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:11,415 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:11,417 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:11,418 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:11,470 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:11,471 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:11,473 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:11,474 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:11,525 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_callback_call_stats_updated(0x24b0270, 0x73c2ecd8, 0x73c2f198) 2016-06-03 14:13:11,527 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_callback_call_stats_updated 2016-06-03 14:13:11,528 [INFO] [doorpi.sipphone.from_linphone] Linphone core [0x24b0270] notifying [call_stats_updated] 2016-06-03 14:13:11,529 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_callback_call_stats_updated(0x24b0270, 0x73c2ecd8, 0x73c2f250) 2016-06-03 14:13:11,530 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_callback_call_stats_updated 2016-06-03 14:13:11,532 [INFO] [doorpi.sipphone.from_linphone] Linphone core [0x24b0270] notifying [call_stats_updated] 2016-06-03 14:13:11,533 [INFO] [doorpi.sipphone.from_linphone] Bandwidth usage for call [0x73c2ecd8]: RTP audio=[d= 80,0,u= 78,4], video=[d= 0,0,u= 0,0] kbits/sec RTCP audio=[d= 0,0,u= 0,0], video=[d= 0,0,u= 0,0] kbits/sec 2016-06-03 14:13:11,534 [INFO] [doorpi.sipphone.from_linphone] Thread processing load: audio=23,025467 video=0,000000 2016-06-03 14:13:11,535 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:11,536 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:11,537 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:11,537 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:11,589 [INFO] [doorpi.sipphone.from_linphone] sound/wall clock skew is average=40,148255 ms 2016-06-03 14:13:11,590 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:11,591 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:11,593 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:11,594 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:11,646 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:11,647 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:11,648 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:11,649 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:11,700 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:11,702 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:11,703 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:11,704 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:11,756 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:11,758 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:11,759 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:11,761 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:11,813 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:11,814 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:11,816 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:11,817 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:11,868 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:11,869 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:11,870 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:11,871 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:11,924 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:11,925 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:11,926 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:11,927 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:11,978 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:11,979 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:11,980 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:11,981 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:12,032 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:12,033 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:12,034 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:12,035 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:12,086 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:12,087 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:12,088 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:12,089 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:12,141 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:12,142 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:12,143 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:12,143 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:12,195 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:12,196 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:12,197 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:12,197 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:12,249 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_state(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:12,250 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_state -> 0x2319868 2016-06-03 14:13:12,251 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_in_call_timeout(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:12,251 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_in_call_timeout -> 0x2319ad4 2016-06-03 14:13:12,303 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8]: received [682] new bytes from [UDP://192.168.16.1:5060]: BYE sip:624@192.168.16.121 SIP/2.0 Via: SIP/2.0/UDP 192.168.16.1:5060;branch=z9hG4bK988392931121B714 From: ;tag=5FEADD4AF6C8C769 To: "DoorPi" ;tag=IJY0rZFYP Call-ID: IxDsspm96- CSeq: 30 BYE X-RTP-Stat: CS=0;PS=466;ES=605;OS=74560;SP=0/0;SO=0;QS=-;PR=590;ER=605;OR=94400;CR=0;SR=0;QR=-;PL=0,0;BL=0;LS=0;RB=0/0;SB=-/-;EN=PCMU;DE=PCMU;JI=86,0;DL=10,4,16;IP=192.168.16.1:7098,192.168.16.121:7078 X-RTP-Stat-Add: DQ=13;DSS=0;DS=0;PLCS=320;JS=61 Reason: Q.850; cause=16 Max-Forwards: 70 User-Agent: AVM FRITZ!Box 7490 113.06.51 (Feb 3 2016) Supported: 100rel,replaces,timer Allow-Events: telephone-event,refer Content-Length: 0 2016-06-03 14:13:12,316 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8] [682] bytes parsed 2016-06-03 14:13:12,317 [INFO] [doorpi.sipphone.from_linphone] Changing [server] [BYE] transaction [0x2541b80], from state [INIT] to [TRYING] 2016-06-03 14:13:12,318 [INFO] [doorpi.sipphone.from_linphone] Changing [server] [BYE] transaction [0x2541b80], from state [TRYING] to [COMPLETED] 2016-06-03 14:13:12,319 [INFO] [doorpi.sipphone.from_linphone] channel [0x24e20c8]: message sent to [UDP://192.168.16.1:5060], size: [273] bytes SIP/2.0 200 Ok Via: SIP/2.0/UDP 192.168.16.1:5060;branch=z9hG4bK988392931121B714 From: ;tag=5FEADD4AF6C8C769 To: "DoorPi" ;tag=IJY0rZFYP Call-ID: IxDsspm96- CSeq: 30 BYE User-Agent: (belle-sip/1.4.2) Supported: outbound 2016-06-03 14:13:12,320 [INFO] [doorpi.sipphone.from_linphone] Dialog [0x24dec30]: now updated by transaction [0x2541b80]. 2016-06-03 14:13:12,321 [INFO] [doorpi.sipphone.from_linphone] dialog [0x24dec30] deleted. 2016-06-03 14:13:12,322 [INFO] [doorpi.sipphone.from_linphone] Current call terminated... 2016-06-03 14:13:12,322 [INFO] [doorpi.sipphone.from_linphone] ms_ticker_set_time_func: ticker's time method updated. 2016-06-03 14:13:12,325 [INFO] [doorpi.sipphone.from_linphone] Filter MSRtpRecv is not scheduled; nothing to do. 2016-06-03 14:13:12,326 [INFO] [doorpi.sipphone.from_linphone] =========================================================== 2016-06-03 14:13:12,327 [INFO] [doorpi.sipphone.from_linphone] AUDIO SESSION'S RTP STATISTICS 2016-06-03 14:13:12,327 [INFO] [doorpi.sipphone.from_linphone] ----------------------------------------------------------- 2016-06-03 14:13:12,328 [INFO] [doorpi.sipphone.from_linphone] sent 597 packets 2016-06-03 14:13:12,328 [INFO] [doorpi.sipphone.from_linphone] 0 duplicated packets 2016-06-03 14:13:12,329 [INFO] [doorpi.sipphone.from_linphone] 102684 bytes 2016-06-03 14:13:12,329 [INFO] [doorpi.sipphone.from_linphone] received 604 packets 2016-06-03 14:13:12,330 [INFO] [doorpi.sipphone.from_linphone] 0 duplicated packets 2016-06-03 14:13:12,331 [INFO] [doorpi.sipphone.from_linphone] 103888 bytes 2016-06-03 14:13:12,331 [INFO] [doorpi.sipphone.from_linphone] incoming delivered to the app 103028 bytes 2016-06-03 14:13:12,332 [INFO] [doorpi.sipphone.from_linphone] incoming cumulative lost 0 packets 2016-06-03 14:13:12,332 [INFO] [doorpi.sipphone.from_linphone] incoming received too late 3 packets 2016-06-03 14:13:12,333 [INFO] [doorpi.sipphone.from_linphone] incoming bad formatted 0 packets 2016-06-03 14:13:12,334 [INFO] [doorpi.sipphone.from_linphone] incoming discarded (queue overflow) 0 packets 2016-06-03 14:13:12,334 [INFO] [doorpi.sipphone.from_linphone] =========================================================== 2016-06-03 14:13:12,335 [INFO] [doorpi.sipphone.from_linphone] ms_filter_unlink: MSAlsaRead:0x24debb0,0-->MSVolume:0x24da498,0 2016-06-03 14:13:12,335 [INFO] [doorpi.sipphone.from_linphone] ms_filter_unlink: MSVolume:0x24da498,0-->MSAudioMixer:0x24dcbc8,0 2016-06-03 14:13:12,336 [INFO] [doorpi.sipphone.from_linphone] ms_filter_unlink: MSAudioMixer:0x24dcbc8,0-->MSUlawEnc:0x253c130,0 2016-06-03 14:13:12,337 [INFO] [doorpi.sipphone.from_linphone] ms_filter_unlink: MSUlawEnc:0x253c130,0-->MSRtpSend:0x73c2d5e0,0 2016-06-03 14:13:12,337 [INFO] [doorpi.sipphone.from_linphone] ms_filter_unlink: MSRtpRecv:0x251d718,0-->MSUlawDec:0x24da3a8,0 2016-06-03 14:13:12,338 [INFO] [doorpi.sipphone.from_linphone] ms_filter_unlink: MSUlawDec:0x24da3a8,0-->MSGenericPLC:0x24b1938,0 2016-06-03 14:13:12,338 [INFO] [doorpi.sipphone.from_linphone] ms_filter_unlink: MSGenericPLC:0x24b1938,0-->MSDtmfGen:0x24de7b0,0 2016-06-03 14:13:12,339 [INFO] [doorpi.sipphone.from_linphone] ms_filter_unlink: MSDtmfGen:0x24de7b0,0-->MSVolume:0x253f798,0 2016-06-03 14:13:12,339 [INFO] [doorpi.sipphone.from_linphone] ms_filter_unlink: MSVolume:0x253f798,0-->MSTee:0x2541898,0 2016-06-03 14:13:12,341 [INFO] [doorpi.sipphone.from_linphone] ms_filter_unlink: MSTee:0x2541898,0-->MSEqualizer:0x24b2c98,0 2016-06-03 14:13:12,341 [INFO] [doorpi.sipphone.from_linphone] ms_filter_unlink: MSEqualizer:0x24b2c98,0-->MSAudioMixer:0x253ec08,0 2016-06-03 14:13:12,342 [INFO] [doorpi.sipphone.from_linphone] ms_filter_unlink: MSFilePlayer:0x24d5358,0-->MSResample:0x251f930,0 2016-06-03 14:13:12,342 [INFO] [doorpi.sipphone.from_linphone] ms_filter_unlink: MSResample:0x251f930,0-->MSAudioMixer:0x253ec08,1 2016-06-03 14:13:12,343 [INFO] [doorpi.sipphone.from_linphone] ms_filter_unlink: MSAudioMixer:0x253ec08,0-->MSAlsaWrite:0x253c030,0 2016-06-03 14:13:12,344 [INFO] [doorpi.sipphone.from_linphone] ms_filter_unlink: MSAudioMixer:0x251ce98,1-->MSResample:0x24b1e30,0 2016-06-03 14:13:12,344 [INFO] [doorpi.sipphone.from_linphone] ms_filter_unlink: MSResample:0x24b1e30,0-->MSOpusEnc:0x24b1848,0 2016-06-03 14:13:12,345 [INFO] [doorpi.sipphone.from_linphone] ms_filter_unlink: MSOpusEnc:0x24b1848,0-->MSMKVRecorder:0x24d72f0,1 2016-06-03 14:13:12,346 [INFO] [doorpi.sipphone.from_linphone] ms_filter_unlink: MSItcSource:0x24caf28,0-->MSMKVRecorder:0x24d72f0,0 2016-06-03 14:13:12,346 [INFO] [doorpi.sipphone.from_linphone] ms_filter_unlink: MSAudioMixer:0x24dcbc8,1-->MSAudioMixer:0x251ce98,0 2016-06-03 14:13:12,347 [INFO] [doorpi.sipphone.from_linphone] ms_filter_unlink: MSTee:0x2541898,1-->MSAudioMixer:0x251ce98,1 2016-06-03 14:13:12,347 [INFO] [doorpi.sipphone.from_linphone] ms_filter_unlink: MSAudioMixer:0x251ce98,0-->MSFileRec:0x2541818,0 2016-06-03 14:13:12,348 [INFO] [doorpi.sipphone.from_linphone] MKVRecorder: destroyed 2016-06-03 14:13:12,349 [INFO] [doorpi.sipphone.from_linphone] =========================================================== 2016-06-03 14:13:12,350 [INFO] [doorpi.sipphone.from_linphone] FILTER USAGE STATISTICS 2016-06-03 14:13:12,350 [INFO] [doorpi.sipphone.from_linphone] Name Count Time/tick (ms) CPU Usage 2016-06-03 14:13:12,351 [INFO] [doorpi.sipphone.from_linphone] ----------------------------------------------------------- 2016-06-03 14:13:12,351 [INFO] [doorpi.sipphone.from_linphone] MSAlsaWrite 651 1,09845 38,538 2016-06-03 14:13:12,352 [INFO] [doorpi.sipphone.from_linphone] MSAlsaRead 1200 0,495197 32,0024 2016-06-03 14:13:12,352 [INFO] [doorpi.sipphone.from_linphone] MSOpusEnc 510 0,754323 20,7415 2016-06-03 14:13:12,353 [INFO] [doorpi.sipphone.from_linphone] MSRtpRecv 1228 0,0346092 2,28878 2016-06-03 14:13:12,354 [INFO] [doorpi.sipphone.from_linphone] MSRtpSend 1200 0,0345259 2,23126 2016-06-03 14:13:12,354 [INFO] [doorpi.sipphone.from_linphone] MSFileRec 510 0,041614 1,14425 2016-06-03 14:13:12,355 [INFO] [doorpi.sipphone.from_linphone] MSAudioMixer 3600 0,00438592 0,849856 2016-06-03 14:13:12,355 [INFO] [doorpi.sipphone.from_linphone] MSVolume 1167 0,00746391 0,469106 2016-06-03 14:13:12,356 [INFO] [doorpi.sipphone.from_linphone] MSUlawEnc 563 0,014666 0,445094 2016-06-03 14:13:12,357 [INFO] [doorpi.sipphone.from_linphone] MSUlawDec 599 0,011761 0,379715 2016-06-03 14:13:12,357 [INFO] [doorpi.sipphone.from_linphone] MSGenericPLC 1200 0,00386878 0,250023 2016-06-03 14:13:12,358 [INFO] [doorpi.sipphone.from_linphone] MSTee 604 0,00411327 0,133908 2016-06-03 14:13:12,358 [INFO] [doorpi.sipphone.from_linphone] MSDtmfGen 1200 0,0020711 0,133846 2016-06-03 14:13:12,359 [INFO] [doorpi.sipphone.from_linphone] MSFilePlayer 1200 0,00175169 0,113204 2016-06-03 14:13:12,360 [INFO] [doorpi.sipphone.from_linphone] MSItcSource 1200 0,0016533 0,106846 2016-06-03 14:13:12,360 [INFO] [doorpi.sipphone.from_linphone] MSEqualizer 604 0,00208895 0,0680055 2016-06-03 14:13:12,361 [INFO] [doorpi.sipphone.from_linphone] MSResample 510 0,00204663 0,0562758 2016-06-03 14:13:12,362 [INFO] [doorpi.sipphone.from_linphone] MSMKVRecorder 255 0,0034808 0,0479492 2016-06-03 14:13:12,362 [INFO] [doorpi.sipphone.from_linphone] MSVoidSink 0 0 0 2016-06-03 14:13:12,363 [INFO] [doorpi.sipphone.from_linphone] MSItcSink 0 0 0 2016-06-03 14:13:12,364 [INFO] [doorpi.sipphone.from_linphone] MSSpeexEC 0 0 0 2016-06-03 14:13:12,364 [INFO] [doorpi.sipphone.from_linphone] =========================================================== 2016-06-03 14:13:12,365 [INFO] [doorpi.sipphone.from_linphone] Call 0x73c2ecd8: moving from state LinphoneCallStreamsRunning to LinphoneCallEnd 2016-06-03 14:13:12,372 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_callback_call_log_updated(0x24b0270, 0x73c2cc78) 2016-06-03 14:13:12,373 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_callback_call_log_updated 2016-06-03 14:13:12,373 [INFO] [doorpi.sipphone.from_linphone] MSAudio MSTicker thread exiting 2016-06-03 14:13:12,374 [INFO] [doorpi.sipphone.from_linphone] Linphone core [0x24b0270] notifying [call_log_updated] 2016-06-03 14:13:12,375 [INFO] [doorpi.sipphone.from_linphone] Resetting the current call 2016-06-03 14:13:12,375 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_callback_call_state_changed(0x24b0270, 0x73c2ecd8, 13, "Call ended") 2016-06-03 14:13:12,376 [DEBUG] [doorpi.sipphone.linphone_lib.CallBacks] call_state_changed (13 - Call ended) 2016-06-03 14:13:12,377 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_remote_address(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:12,377 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Address_from_native_ptr(0x73c03658) 2016-06-03 14:13:12,378 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Address_new() 2016-06-03 14:13:12,378 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Address_new -> 0x76cd75e0 2016-06-03 14:13:12,379 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Address_init() 2016-06-03 14:13:12,379 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Address_init -> 0x76cd75e0 2016-06-03 14:13:12,380 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Address_from_native_ptr -> 0x76cd75e0 2016-06-03 14:13:12,381 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_remote_address -> 0x76cd75e0 2016-06-03 14:13:12,381 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Address_instance_method_as_string_uri_only(0x76cd75e0 [0x73c03658]) 2016-06-03 14:13:12,382 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Address_instance_method_as_string_uri_only -> 0x72f472f0 2016-06-03 14:13:12,382 [TRACE] [doorpi.action.handler] fire Event OnCallStateChange from doorpi.sipphone.linphone_lib.CallBacks asyncron 2016-06-03 14:13:12,384 [TRACE] [doorpi.action.handler] fire Event OnCallStateDisconnect from doorpi.sipphone.linphone_lib.CallBacks asyncron 2016-06-03 14:13:12,386 [DEBUG] [doorpi.action.handler] no actions for event OnCallStateChange - skip fire_event OnCallStateChange from doorpi.sipphone.linphone_lib.CallBacks 2016-06-03 14:13:12,387 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_calls_nb(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:12,388 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_calls_nb -> 0x23198bc 2016-06-03 14:13:12,388 [DEBUG] [doorpi.action.handler] [VVQY17] fire for event OnCallStateDisconnect this actions [, ] 2016-06-03 14:13:12,389 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_calls_nb(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:12,390 [TRACE] [doorpi.action.handler] [VVQY17] try to fire action > with args () and kwargs {} 2016-06-03 14:13:12,390 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_calls_nb -> 0x23198bc 2016-06-03 14:13:12,391 [TRACE] [doorpi.action.base] run SingleAction with args () and kwargs {} 2016-06-03 14:13:12,391 [TRACE] [doorpi.action.handler] fire Event OnMediaNotRequired from doorpi.sipphone.linphone_lib.CallBacks asyncron 2016-06-03 14:13:12,392 [TRACE] [doorpi.action.handler] fire Event OnPlayerStopped from doorpi.sipphone.linphone_lib.Player asyncron 2016-06-03 14:13:12,395 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_calls_nb(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:12,397 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_calls_nb -> 0x23198bc 2016-06-03 14:13:12,397 [DEBUG] [doorpi.action.handler] no actions for event OnPlayerStopped - skip fire_event OnPlayerStopped from doorpi.sipphone.linphone_lib.Player 2016-06-03 14:13:12,398 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_callback_call_state_changed 2016-06-03 14:13:12,398 [TRACE] [doorpi.action.handler] [VVQY17] try to fire action > with args () and kwargs {} 2016-06-03 14:13:12,400 [TRACE] [doorpi.action.base] run SingleAction with args () and kwargs {} 2016-06-03 14:13:12,399 [INFO] [doorpi.sipphone.from_linphone] Linphone core [0x24b0270] notifying [call_state_changed] 2016-06-03 14:13:12,399 [DEBUG] [doorpi.action.handler] no actions for event OnMediaNotRequired - skip fire_event OnMediaNotRequired from doorpi.sipphone.linphone_lib.CallBacks 2016-06-03 14:13:12,402 [TRACE] [doorpi.action.handler] [VVQY17] finished fire_event for event_name OnCallStateDisconnect 2016-06-03 14:13:12,452 [INFO] [doorpi.sipphone.from_linphone] Dialog [0x24dec30] terminated for op [0x73c2d200] 2016-06-03 14:13:12,503 [INFO] [doorpi.sipphone.from_linphone] Call 0x73c2ecd8: moving from state LinphoneCallEnd to LinphoneCallReleased 2016-06-03 14:13:12,503 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_callback_call_state_changed(0x24b0270, 0x73c2ecd8, 18, "Call released") 2016-06-03 14:13:12,504 [DEBUG] [doorpi.sipphone.linphone_lib.CallBacks] call_state_changed (18 - Call released) 2016-06-03 14:13:12,504 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Call_get_remote_address(0x76cd7560 [0x73c2ecd8]) 2016-06-03 14:13:12,504 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Address_from_native_ptr(0x73c03658) 2016-06-03 14:13:12,504 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Address_new() 2016-06-03 14:13:12,505 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Address_new -> 0x76cd7600 2016-06-03 14:13:12,505 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Address_init() 2016-06-03 14:13:12,505 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Address_init -> 0x76cd7600 2016-06-03 14:13:12,505 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Address_from_native_ptr -> 0x76cd7600 2016-06-03 14:13:12,506 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Call_get_remote_address -> 0x76cd7600 2016-06-03 14:13:12,506 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Address_instance_method_as_string_uri_only(0x76cd7600 [0x73c03658]) 2016-06-03 14:13:12,506 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Address_instance_method_as_string_uri_only -> 0x72f47318 2016-06-03 14:13:12,506 [TRACE] [doorpi.action.handler] fire Event OnCallStateChange from doorpi.sipphone.linphone_lib.CallBacks asyncron 2016-06-03 14:13:12,508 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_calls_nb(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:12,508 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_calls_nb -> 0x23198bc 2016-06-03 14:13:12,508 [DEBUG] [doorpi.action.handler] no actions for event OnCallStateChange - skip fire_event OnCallStateChange from doorpi.sipphone.linphone_lib.CallBacks 2016-06-03 14:13:12,509 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_calls_nb(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:12,509 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_calls_nb -> 0x23198bc 2016-06-03 14:13:12,510 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] >>> pylinphone_Core_get_calls_nb(0x75b29c38 [0x24b0270]) 2016-06-03 14:13:12,510 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_get_calls_nb -> 0x23198bc 2016-06-03 14:13:12,510 [DEBUG] [doorpi.sipphone.from_linphone] [PYLINPHONE] <<< pylinphone_Core_callback_call_state_changed 2016-06-03 14:13:12,511 [INFO] [doorpi.sipphone.from_linphone] Linphone core [0x24b0270] notifying [call_state_changed] 2016-06-03 14:13:12,511 [INFO] [doorpi.sipphone.from_linphone] op [0x73c2d200] : set_or_update_dialog() current=[0x24dec30] new=[(nil)]