## Normaler Startup log, gekürzt, es folgt der Log vom ersten Anruf ## [2018-04-27 10:01:55.359] [Debug] [service.MdSoftphone] unknown:0 - Add outbound call id -1, now 1 calls [2018-04-27 10:01:55.359] [Debug] [service.MdSoftphone] unknown:0 - Thread id mdsoftphone: threadID= QThread(0x20ff890) [2018-04-27 10:01:55.360] [Debug] [proto.sip] unknown:0 - "10:01:55.360 pjsua_call.c !Making call with acc #0 to sip:*9001@pascom" [2018-04-27 10:01:55.360] [Debug] [proto.sip] unknown:0 - "10:01:55.360 pjsua_aud.c .Set sound device: capture=0, playback=0" [2018-04-27 10:01:55.360] [Debug] [proto.sip] unknown:0 - "10:01:55.360 pjsua_aud.c ..Opening sound device (speaker + mic) PCM@16000/1/20ms" [2018-04-27 10:01:55.360] [Debug] [proto.sip] unknown:0 - "10:01:55.360 alsa_dev.c ...open_playback: Open playback device 'pulse'" [2018-04-27 10:01:55.365] [Debug] [proto.sip] unknown:0 - "10:01:55.365 alsa_dev.c ...Opened device alsa(pulse) for playing, sample rate=16000, ch=1, bits=16, period size=320 frames, latency=140 ms" [2018-04-27 10:01:55.365] [Debug] [proto.sip] unknown:0 - "10:01:55.365 alsa_dev.c ...open_capture: Open capture device 'pulse'" [2018-04-27 10:01:55.370] [Debug] [proto.sip] unknown:0 - "10:01:55.370 alsa_dev.c ...Opened device alsa(pulse) for capture, sample rate=16000, ch=1, bits=16, period size=320 frames, latency=100 ms" [2018-04-27 10:01:55.370] [Debug] [proto.sip] unknown:0 - "10:01:55.370 dlg0x3c46578 .UAC dialog created" [2018-04-27 10:01:55.370] [Debug] [proto.sip] unknown:0 - "10:01:55.370 dlg0x3c46578 ..Session count inc to 2 by mod-pjsua" [2018-04-27 10:01:55.370] [Debug] [proto.sip] unknown:0 - "10:01:55.370 pjsua_media.c .Call 0: initializing media.." [2018-04-27 10:01:55.370] [Debug] [proto.sip] unknown:0 - "10:01:55.370 pjsua_media.c !..RTP socket reachable at 192.168.42.48:4000" [2018-04-27 10:01:55.370] [Debug] [proto.sip] unknown:0 - "10:01:55.370 alsa_dev.c !ca_thread_func(17821): Set thread priority for audio capture thread." [2018-04-27 10:01:55.370] [Debug] [proto.sip] unknown:0 - "10:01:55.370 pjsua_media.c ..RTCP socket reachable at 192.168.42.48:4001" [2018-04-27 10:01:55.370] [Debug] [proto.sip] unknown:0 - "10:01:55.370 srtp0x3ab59d0 ..SRTP keying SDES created" [2018-04-27 10:01:55.370] [Debug] [proto.sip] unknown:0 - "10:01:55.370 pjsua_media.c ..Media index 0 selected for audio call 0" [2018-04-27 10:01:55.370] [Debug] [proto.sip] unknown:0 - "10:01:55.370 pjsua_media.c ..Call 0: media transport initialization complete: Success" [2018-04-27 10:01:55.370] [Debug] [proto.sip] unknown:0 - "10:01:55.370 dlg0x3c46578 ..Session count dec to 2 by mod-pjsua" [2018-04-27 10:01:55.370] [Debug] [proto.sip] unknown:0 - "10:01:55.370 dlg0x3c46578 .Module mod-invite added as dialog usage, data=0x3cecdd8" [2018-04-27 10:01:55.370] [Debug] [proto.sip] unknown:0 - "10:01:55.370 dlg0x3c46578 ..Session count inc to 4 by mod-invite" [2018-04-27 10:01:55.370] [Debug] [proto.sip] unknown:0 - "10:01:55.370 dlg0x3c46578 .Module mod-100rel added as dialog usage, data=0x3cf70d0" [2018-04-27 10:01:55.370] [Debug] [proto.sip] unknown:0 - "10:01:55.370 dlg0x3c46578 .100rel module attached" [2018-04-27 10:01:55.370] [Debug] [proto.sip] unknown:0 - "10:01:55.370 inv0x3c46578 .UAC invite session created for dialog dlg0x3c46578" [2018-04-27 10:01:55.370] [Debug] [proto.sip] unknown:0 - "10:01:55.370 endpoint .Request msg INVITE/cseq=15620 (tdta0x3d4ce38) created." [2018-04-27 10:01:55.370] [Debug] [proto.sip] unknown:0 - "10:01:55.370 inv0x3c46578 ..Sending Request msg INVITE/cseq=15620 (tdta0x3d4ce38)" [2018-04-27 10:01:55.370] [Debug] [proto.sip] unknown:0 - "10:01:55.370 dlg0x3c46578 ...Sending Request msg INVITE/cseq=15620 (tdta0x3d4ce38)" [2018-04-27 10:01:55.371] [Debug] [proto.sip] unknown:0 - "10:01:55.371 tsx0x2f37e68 ....Transaction created for Request msg INVITE/cseq=15619 (tdta0x3d4ce38)" [2018-04-27 10:01:55.371] [Debug] [proto.sip] unknown:0 - "10:01:55.371 tsx0x2f37e68 ...Sending Request msg INVITE/cseq=15619 (tdta0x3d4ce38) in state Null" [2018-04-27 10:01:55.371] [Debug] [proto.sip] unknown:0 - "10:01:55.371 sip_resolve.c ....Target '192.168.42.200:0' type=Unspecified resolved to '192.168.42.200:5060' type=UDP (UDP transport)" [2018-04-27 10:01:55.371] [Debug] [proto.sip] unknown:0 - "10:01:55.371 pjsua_core.c ....TX 1143 bytes Request msg INVITE/cseq=15619 (tdta0x3d4ce38) to UDP 192.168.42.200:5060: INVITE sip:*9001@pascom SIP/2.0\r Via: SIP/2.0/UDP 192.168.42.48:54418;rport;branch=z9hG4bKPj963b9837-3075-4242-814a-d45b90aa7fea\r Max-Forwards: 70\r From: sip:XJ15zaZnchCOaOh@pascom;tag=152d75ac-6728-4e85-b8c1-01102994125a\r To: sip:*9001@pascom\r Contact: <sip:XJ15zaZnchCOaOh@192.168.42.48:54418;ob>\r Call-ID: 8c1e6478-8443-40a7-b16b-813ff3cc4a8e\r CSeq: 15619 INVITE\r Route: <sip:192.168.42.200;lr>\r Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS\r Supported: replaces, 100rel, timer, norefersub\r Session-Expires: 1800\r Min-SE: 90\r User-Agent: admin@pascom/HzFl\r Content-Type: application/sdp\r Content-Length: 476\r \r v=0\r o=- 3733804915 3733804915 IN IP4 192.168.42.48\r s=pjmedia\r b=AS:84\r t=0 0\r a=X-nat:0\r m=audio 4000 RTP/AVP 98 97 99 104 3 0 8 9 96\r c=IN IP4 192.168.42.48\r b=TIAS:64000\r a=rtcp:4001 IN IP4 192.168.42.48\r a=sendrecv\r a=rtpmap:98 speex/16000\r a=rtpmap:97 speex/8000\r a=rtpmap:99 speex/32000\r a=rtpmap:104 iLBC/8000\r a=fmtp:104 mode=30\r a=rtpmap:3 GSM/8000\r a=rtpmap:0 PCMU/8000\r a=rtpmap:8 PCMA/8000\r a=rtpmap:9 G722/8000\r a=rtpmap:96 telephone-event/8000\r a=fmtp:96 0-16\r --end msg--" [2018-04-27 10:01:55.371] [Debug] [proto.sip] unknown:0 - "10:01:55.371 tsx0x2f37e68 ....State changed from Null to Calling, event=TX_MSG" [2018-04-27 10:01:55.371] [Debug] [proto.sip] unknown:0 - "10:01:55.371 dlg0x3c46578 .....Transaction tsx0x2f37e68 state changed to Calling" [2018-04-27 10:01:55.372] [Debug] [proto.sip] unknown:0 - "10:01:55.372 sip_endpoint.c !Processing incoming message: Response msg 401/INVITE/cseq=15619 (rdata0x7fbdcc013ee8)" [2018-04-27 10:01:55.372] [Debug] [proto.sip] unknown:0 - "10:01:55.372 pjsua_core.c .RX 581 bytes Response msg 401/INVITE/cseq=15619 (rdata0x7fbdcc013ee8) from UDP 192.168.42.200:5060: SIP/2.0 401 Unauthorized\r Via: SIP/2.0/UDP 192.168.42.48:54418;branch=z9hG4bKPj963b9837-3075-4242-814a-d45b90aa7fea;received=192.168.42.48;rport=54418\r From: sip:XJ15zaZnchCOaOh@pascom;tag=152d75ac-6728-4e85-b8c1-01102994125a\r To: sip:*9001@pascom;tag=as30db0118\r Call-ID: 8c1e6478-8443-40a7-b16b-813ff3cc4a8e\r CSeq: 15619 INVITE\r Server: Asterisk PBX certified/11.6-cert17\r Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH\r Supported: replaces, timer\r WWW-Authenticate: Digest algorithm=MD5, realm=\"pascom\", nonce=\"6f9fab09\"\r Content-Length: 0\r \r --end msg--" [2018-04-27 10:01:55.372] [Debug] [proto.sip] unknown:0 - "10:01:55.372 tsx0x2f37e68 .Incoming Response msg 401/INVITE/cseq=15619 (rdata0x7fbdcc013ee8) in state Calling" [2018-04-27 10:01:55.372] [Debug] [proto.sip] unknown:0 - "10:01:55.372 endpoint ..Request msg ACK/cseq=15619 (tdta0x7fbdcc0193f8) created." [2018-04-27 10:01:55.372] [Debug] [proto.sip] unknown:0 - "10:01:55.372 pjsua_core.c ..TX 375 bytes Request msg ACK/cseq=15619 (tdta0x7fbdcc0193f8) to UDP 192.168.42.200:5060: ACK sip:*9001@pascom SIP/2.0\r Via: SIP/2.0/UDP 192.168.42.48:54418;rport;branch=z9hG4bKPj963b9837-3075-4242-814a-d45b90aa7fea\r Max-Forwards: 70\r From: sip:XJ15zaZnchCOaOh@pascom;tag=152d75ac-6728-4e85-b8c1-01102994125a\r To: sip:*9001@pascom;tag=as30db0118\r Call-ID: 8c1e6478-8443-40a7-b16b-813ff3cc4a8e\r CSeq: 15619 ACK\r Route: <sip:192.168.42.200;lr>\r Content-Length: 0\r \r --end msg--" [2018-04-27 10:01:55.372] [Debug] [proto.sip] unknown:0 - "10:01:55.372 tsx0x2f37e68 ..State changed from Calling to Completed, event=RX_MSG" [2018-04-27 10:01:55.372] [Debug] [proto.sip] unknown:0 - "10:01:55.372 dlg0x3c46578 ...Received Response msg 401/INVITE/cseq=15619 (rdata0x7fbdcc013ee8)" [2018-04-27 10:01:55.372] [Debug] [proto.sip] unknown:0 - "10:01:55.372 dlg0x3c46578 ...Transaction tsx0x2f37e68 state changed to Completed" [2018-04-27 10:01:55.372] [Debug] [proto.sip] unknown:0 - "10:01:55.372 inv0x3c46578 .....Sending Request msg INVITE/cseq=15619 (tdta0x3d4ce38)" [2018-04-27 10:01:55.372] [Debug] [proto.sip] unknown:0 - "10:01:55.372 dlg0x3c46578 ......Sending Request msg INVITE/cseq=15619 (tdta0x3d4ce38)" [2018-04-27 10:01:55.372] [Debug] [proto.sip] unknown:0 - "10:01:55.372 tsx0x7fbdcc01e2a8 .......Transaction created for Request msg INVITE/cseq=15620 (tdta0x3d4ce38)" [2018-04-27 10:01:55.372] [Debug] [proto.sip] unknown:0 - "10:01:55.372 tsx0x7fbdcc01e2a8 ......Sending Request msg INVITE/cseq=15620 (tdta0x3d4ce38) in state Null" [2018-04-27 10:01:55.372] [Debug] [proto.sip] unknown:0 - "10:01:55.372 endpoint .......Request msg INVITE/cseq=15620 (tdta0x3d4ce38): skipping target resolution because address is already set" [2018-04-27 10:01:55.372] [Debug] [proto.sip] unknown:0 - "10:01:55.372 pjsua_core.c .......TX 1311 bytes Request msg INVITE/cseq=15620 (tdta0x3d4ce38) to UDP 192.168.42.200:5060: INVITE sip:*9001@pascom SIP/2.0\r Via: SIP/2.0/UDP 192.168.42.48:54418;rport;branch=z9hG4bKPjb7d4b82d-898e-4e04-915b-295970ad3d3c\r Max-Forwards: 70\r From: sip:XJ15zaZnchCOaOh@pascom;tag=152d75ac-6728-4e85-b8c1-01102994125a\r To: sip:*9001@pascom\r Contact: <sip:XJ15zaZnchCOaOh@192.168.42.48:54418;ob>\r Call-ID: 8c1e6478-8443-40a7-b16b-813ff3cc4a8e\r CSeq: 15620 INVITE\r Route: <sip:192.168.42.200;lr>\r Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS\r Supported: replaces, 100rel, timer, norefersub\r Session-Expires: 1800\r Min-SE: 90\r User-Agent: admin@pascom/HzFl\r Authorization: Digest username=\"XJ15zaZnchCOaOh\", realm=\"pascom\", nonce=\"6f9fab09\", uri=\"sip:*9001@pascom\", response=\"ee1249e4dfb871b91552e5e35b04397c\", algorithm=MD5\r Content-Type: application/sdp\r Content-Length: 476\r \r v=0\r o=- 3733804915 3733804915 IN IP4 192.168.42.48\r s=pjmedia\r b=AS:84\r t=0 0\r a=X-nat:0\r m=audio 4000 RTP/AVP 98 97 99 104 3 0 8 9 96\r c=IN IP4 192.168.42.48\r b=TIAS:64000\r a=rtcp:4001 IN IP4 192.168.42.48\r a=sendrecv\r a=rtpmap:98 speex/16000\r a=rtpmap:97 speex/8000\r a=rtpmap:99 speex/32000\r a=rtpmap:104 iLBC/8000\r a=fmtp:104 mode=30\r a=rtpmap:3 GSM/8000\r a=rtpmap:0 PCMU/8000\r a=rtpmap:8 PCMA/8000\r a=rtpmap:9 G722/8000\r a=rtpmap:96 telephone-event/8000\r a=fmtp:96 0-16\r --end msg--" [2018-04-27 10:01:55.372] [Debug] [proto.sip] unknown:0 - "10:01:55.372 tsx0x7fbdcc01e2a8 .......State changed from Null to Calling, event=TX_MSG" [2018-04-27 10:01:55.372] [Debug] [proto.sip] unknown:0 - "10:01:55.372 dlg0x3c46578 ........Transaction tsx0x7fbdcc01e2a8 state changed to Calling" [2018-04-27 10:01:55.374] [Debug] [proto.sip] unknown:0 - "10:01:55.374 sip_endpoint.c Processing incoming message: Response msg 100/INVITE/cseq=15620 (rdata0x7fbdcc013ee8)" [2018-04-27 10:01:55.374] [Debug] [proto.sip] unknown:0 - "10:01:55.374 pjsua_core.c .RX 565 bytes Response msg 100/INVITE/cseq=15620 (rdata0x7fbdcc013ee8) from UDP 192.168.42.200:5060: SIP/2.0 100 Trying\r Via: SIP/2.0/UDP 192.168.42.48:54418;branch=z9hG4bKPjb7d4b82d-898e-4e04-915b-295970ad3d3c;received=192.168.42.48;rport=54418\r From: sip:XJ15zaZnchCOaOh@pascom;tag=152d75ac-6728-4e85-b8c1-01102994125a\r To: sip:*9001@pascom\r Call-ID: 8c1e6478-8443-40a7-b16b-813ff3cc4a8e\r CSeq: 15620 INVITE\r Server: Asterisk PBX certified/11.6-cert17\r Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH\r Supported: replaces, timer\r Session-Expires: 1800;refresher=uas\r Contact: <sip:*9001@192.168.42.200:5060>\r Content-Length: 0\r \r --end msg--" [2018-04-27 10:01:55.374] [Debug] [proto.sip] unknown:0 - "10:01:55.374 tsx0x7fbdcc01e2a8 .Incoming Response msg 100/INVITE/cseq=15620 (rdata0x7fbdcc013ee8) in state Calling" [2018-04-27 10:01:55.374] [Debug] [proto.sip] unknown:0 - "10:01:55.374 tsx0x7fbdcc01e2a8 ..State changed from Calling to Proceeding, event=RX_MSG" [2018-04-27 10:01:55.374] [Debug] [proto.sip] unknown:0 - "10:01:55.374 dlg0x3c46578 ...Received Response msg 100/INVITE/cseq=15620 (rdata0x7fbdcc013ee8)" [2018-04-27 10:01:55.374] [Debug] [proto.sip] unknown:0 - "10:01:55.374 dlg0x3c46578 ...Transaction tsx0x7fbdcc01e2a8 state changed to Proceeding" [2018-04-27 10:01:55.381] [Debug] [proto.sip] unknown:0 - "10:01:55.381 sip_endpoint.c Processing incoming message: Response msg 200/INVITE/cseq=15620 (rdata0x7fbdcc013ee8)" [2018-04-27 10:01:55.381] [Debug] [proto.sip] unknown:0 - "10:01:55.381 pjsua_core.c .RX 926 bytes Response msg 200/INVITE/cseq=15620 (rdata0x7fbdcc013ee8) from UDP 192.168.42.200:5060: SIP/2.0 200 OK\r Via: SIP/2.0/UDP 192.168.42.48:54418;branch=z9hG4bKPjb7d4b82d-898e-4e04-915b-295970ad3d3c;received=192.168.42.48;rport=54418\r From: sip:XJ15zaZnchCOaOh@pascom;tag=152d75ac-6728-4e85-b8c1-01102994125a\r To: sip:*9001@pascom;tag=as02514e3d\r Call-ID: 8c1e6478-8443-40a7-b16b-813ff3cc4a8e\r CSeq: 15620 INVITE\r Server: Asterisk PBX certified/11.6-cert17\r Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH\r Supported: replaces, timer\r Session-Expires: 1800;refresher=uas\r Contact: <sip:*9001@192.168.42.200:5060>\r Content-Type: application/sdp\r Require: timer\r Content-Length: 301\r \r v=0\r o=root 1392639180 1392639180 IN IP4 192.168.42.200\r s=Asterisk PBX certified/11.6-cert17\r c=IN IP4 192.168.42.200\r t=0 0\r m=audio 15560 RTP/AVP 8 0 3 101\r a=rtpmap:8 PCMA/8000\r a=rtpmap:0 PCMU/8000\r a=rtpmap:3 GSM/8000\r a=rtpmap:101 telephone-event/8000\r a=fmtp:101 0-16\r a=ptime:20\r a=sendrecv\r --end msg--" [2018-04-27 10:01:55.381] [Debug] [proto.sip] unknown:0 - "10:01:55.381 tsx0x7fbdcc01e2a8 .Incoming Response msg 200/INVITE/cseq=15620 (rdata0x7fbdcc013ee8) in state Proceeding" [2018-04-27 10:01:55.381] [Debug] [proto.sip] unknown:0 - "10:01:55.381 tsx0x7fbdcc01e2a8 ..State changed from Proceeding to Terminated, event=RX_MSG" [2018-04-27 10:01:55.381] [Debug] [proto.sip] unknown:0 - "10:01:55.381 dlg0x3c46578 ...Received Response msg 200/INVITE/cseq=15620 (rdata0x7fbdcc013ee8)" [2018-04-27 10:01:55.381] [Debug] [proto.sip] unknown:0 - "10:01:55.381 dlg0x3c46578 ....Route-set updated" [2018-04-27 10:01:55.381] [Debug] [proto.sip] unknown:0 - "10:01:55.381 dlg0x3c46578 ....Route-set frozen" [2018-04-27 10:01:55.381] [Debug] [proto.sip] unknown:0 - "10:01:55.381 dlg0x3c46578 ...Transaction tsx0x7fbdcc01e2a8 state changed to Terminated" [2018-04-27 10:01:55.381] [Debug] [proto.sip] unknown:0 - "10:01:55.381 inv0x3c46578 ....Got SDP answer in Response msg 200/INVITE/cseq=15620 (rdata0x7fbdcc013ee8)" [2018-04-27 10:01:55.382] [Debug] [proto.sip] unknown:0 - "10:01:55.382 inv0x3c46578 ....SDP negotiation done, status=0" [2018-04-27 10:01:55.382] [Debug] [proto.sip] unknown:0 - "10:01:55.382 pjsua_call.c .....Call 0: remote NAT type is 0 (Unknown)" [2018-04-27 10:01:55.382] [Debug] [proto.sip] unknown:0 - "10:01:55.382 pjsua_media.c .....Call 0: updating media.." [2018-04-27 10:01:55.382] [Debug] [proto.sip] unknown:0 - "10:01:55.382 pjsua_media.c .......Media stream call00:0 is destroyed" [2018-04-27 10:01:55.382] [Debug] [proto.sip] unknown:0 - "10:01:55.382 pjsua_aud.c ......Audio channel update.." [2018-04-27 10:01:55.382] [Debug] [proto.sip] unknown:0 - "10:01:55.382 rtp.c .......pjmedia_rtp_session_init: ses=0x7fbdcc022ee4, default_pt=8, ssrc=0x567bd452" [2018-04-27 10:01:55.382] [Debug] [proto.sip] unknown:0 - "10:01:55.382 rtp.c .......pjmedia_rtp_session_init: ses=0x7fbdcc023564, default_pt=8, ssrc=0x567bd452" [2018-04-27 10:01:55.382] [Debug] [proto.sip] unknown:0 - "10:01:55.382 stream.c .......Stream strm0x7fbdcc020848 created" [2018-04-27 10:01:55.382] [Debug] [proto.sip] unknown:0 - "10:01:55.382 strm0x7fbdcc020848 .......Encoder stream started" [2018-04-27 10:01:55.382] [Debug] [proto.sip] unknown:0 - "10:01:55.382 strm0x7fbdcc020848 .......Decoder stream started" [2018-04-27 10:01:55.382] [Debug] [proto.sip] unknown:0 - "10:01:55.382 resample.c .......resample created: high qualiy, large filter, in/out rate=8000/16000" [2018-04-27 10:01:55.382] [Debug] [proto.sip] unknown:0 - "10:01:55.382 resample.c .......resample created: high qualiy, large filter, in/out rate=16000/8000" [2018-04-27 10:01:55.382] [Debug] [proto.sip] unknown:0 - "10:01:55.382 pjsua_media.c ......Audio updated, stream #0: PCMA (sendrecv)" [2018-04-27 10:01:55.382] [Info] [util.MdCall] unknown:0 - Media State change, Call State is now 4 [2018-04-27 10:01:55.382] [Debug] [proto.sip] unknown:0 - "10:01:55.382 inv0x3c46578 ....Received Response msg 200/INVITE/cseq=15620 (rdata0x7fbdcc013ee8), sending ACK" [2018-04-27 10:01:55.382] [Debug] [proto.sip] unknown:0 - "10:01:55.382 endpoint ....Request msg ACK/cseq=15620 (tdta0x7fbdcc025528) created." [2018-04-27 10:01:55.382] [Debug] [proto.sip] unknown:0 - "10:01:55.382 dlg0x3c46578 .....Sending Request msg ACK/cseq=15620 (tdta0x7fbdcc025528)" [2018-04-27 10:01:55.382] [Debug] [proto.sip] unknown:0 - "10:01:55.382 sip_resolve.c .....Target '192.168.42.200:5060' type=Unspecified resolved to '192.168.42.200:5060' type=UDP (UDP transport)" [2018-04-27 10:01:55.382] [Debug] [proto.sip] unknown:0 - "10:01:55.382 pjsua_core.c .....TX 356 bytes Request msg ACK/cseq=15620 (tdta0x7fbdcc025528) to UDP 192.168.42.200:5060: ACK sip:*9001@192.168.42.200:5060 SIP/2.0\r Via: SIP/2.0/UDP 192.168.42.48:54418;rport;branch=z9hG4bKPjf8873526-0717-4569-b010-a398f41528e2\r Max-Forwards: 70\r From: sip:XJ15zaZnchCOaOh@pascom;tag=152d75ac-6728-4e85-b8c1-01102994125a\r To: sip:*9001@pascom;tag=as02514e3d\r Call-ID: 8c1e6478-8443-40a7-b16b-813ff3cc4a8e\r CSeq: 15620 ACK\r Content-Length: 0\r \r --end msg--" [2018-04-27 10:01:55.382] [Debug] [proto.sip] unknown:0 - "10:01:55.382 tsx0x7fbdcc01e2a8 Timeout timer event" [2018-04-27 10:01:55.382] [Debug] [proto.sip] unknown:0 - "10:01:55.382 tsx0x7fbdcc01e2a8 .State changed from Terminated to Destroyed, event=TIMER" [2018-04-27 10:01:55.382] [Debug] [proto.sip] unknown:0 - "10:01:55.382 tsx0x7fbdcc01e2a8 Transaction destroyed!" [2018-04-27 10:01:55.392] [Debug] [proto.sip] unknown:0 - "10:01:55.392 pjsua_aud.c !Conf connect: 0 --> 2" [2018-04-27 10:01:55.392] [Debug] [proto.sip] unknown:0 - "10:01:55.392 conference.c .Port 0 (pulse) transmitting to port 2 (sip:*9001@pascom)" [2018-04-27 10:01:55.392] [Debug] [proto.sip] unknown:0 - "10:01:55.392 pjsua_aud.c Conf connect: 2 --> 0" [2018-04-27 10:01:55.392] [Debug] [proto.sip] unknown:0 - "10:01:55.392 conference.c .Port 2 (sip:*9001@pascom) transmitting to port 0 (pulse)" [2018-04-27 10:01:55.401] [Debug] [proto.sip] unknown:0 - "10:01:55.401 Master/sound !Underflow, buf_cnt=0, will generate 1 frame" [2018-04-27 10:01:55.401] [Debug] [proto.sip] unknown:0 - "10:01:55.401 strm0x7fbdcc020848 Jitter buffer is bufferring (prefetch=0)" [2018-04-27 10:01:55.401] [Debug] [proto.sip] unknown:0 - "10:01:55.401 strm0x7fbdcc020848 Start talksprut.." [2018-04-27 10:01:55.432] [Debug] [proto.sip] unknown:0 - "10:01:55.432 Master/sound Underflow, buf_cnt=0, will generate 1 frame" [2018-04-27 10:01:55.442] [Info] [service.PhonecallService] unknown:0 - phonecall created id 107713 [2018-04-27 10:01:55.442] [Info] [service.PhonecallService] unknown:0 - Add channel for device "pascom Softphone [Bernd Helm]" [2018-04-27 10:01:55.484] [Info] [service.UILoader] unknown:0 - Loading component "view/call/CallNotification.qml" [2018-04-27 10:01:55.493] [Debug] [proto.sip] unknown:0 - "10:01:55.493 Master/sound Underflow, buf_cnt=0, will generate 1 frame" [2018-04-27 10:01:55.669] [Debug] [proto.sip] unknown:0 - "10:01:55.669 strm0x7fbdcc020848 !RTP status: badpt=0, badssrc=0, dup=0, outorder=0, probation=-1, restart=0" [2018-04-27 10:01:55.675] [Debug] [proto.sip] unknown:0 - "10:01:55.675 strm0x7fbdcc020848 !Jitter buffer starts returning normal frames (after 14 empty/lost)" [2018-04-27 10:01:56.238] [Debug] [proto.sip] unknown:0 - "10:01:56.238 strm0x7fbdcc020848 Frame lost, recovered!" [2018-04-27 10:01:56.238] [Debug] [proto.sip] unknown:0 - "10:01:56.238 strm0x7fbdcc020848 Jitter buffer starts returning normal frames (after 1 empty/lost)" [2018-04-27 10:01:56.421] [Debug] [proto.sip] unknown:0 - "10:01:56.421 strm0x7fbdcc020848 Frame lost, recovered!" [2018-04-27 10:01:56.440] [Debug] [proto.sip] unknown:0 - "10:01:56.440 strm0x7fbdcc020848 Jitter buffer starts returning normal frames (after 1 empty/lost)" [2018-04-27 10:01:56.620] [Debug] [proto.sip] unknown:0 - "10:01:56.620 strm0x7fbdcc020848 Frame lost, recovered!" [2018-04-27 10:01:56.620] [Debug] [proto.sip] unknown:0 - "10:01:56.620 strm0x7fbdcc020848 Jitter buffer starts returning normal frames (after 1 empty/lost)" [2018-04-27 10:01:56.796] [Debug] [proto.sip] unknown:0 - "10:01:56.796 strm0x7fbdcc020848 Frame lost, recovered!" [2018-04-27 10:01:56.816] [Debug] [proto.sip] unknown:0 - "10:01:56.816 strm0x7fbdcc020848 Jitter buffer starts returning normal frames (after 1 empty/lost)" [2018-04-27 10:01:56.999] [Debug] [proto.sip] unknown:0 - "10:01:56.999 strm0x7fbdcc020848 Frame lost, recovered!" [2018-04-27 10:01:57.000] [Debug] [proto.sip] unknown:0 - "10:01:57.000 strm0x7fbdcc020848 Jitter buffer starts returning normal frames (after 1 empty/lost)" [2018-04-27 10:01:57.179] [Debug] [proto.sip] unknown:0 - "10:01:57.179 strm0x7fbdcc020848 Frame lost, recovered!" [2018-04-27 10:01:57.200] [Debug] [proto.sip] unknown:0 - "10:01:57.200 strm0x7fbdcc020848 Jitter buffer starts returning normal frames (after 1 empty/lost)" [2018-04-27 10:01:57.380] [Debug] [proto.sip] unknown:0 - "10:01:57.380 strm0x7fbdcc020848 Frame lost, recovered!" [2018-04-27 10:01:57.380] [Debug] [proto.sip] unknown:0 - "10:01:57.380 strm0x7fbdcc020848 Jitter buffer starts returning normal frames (after 1 empty/lost)" [2018-04-27 10:01:57.562] [Debug] [proto.sip] unknown:0 - "10:01:57.562 strm0x7fbdcc020848 Frame lost, recovered!" [2018-04-27 10:01:57.581] [Debug] [proto.sip] unknown:0 - "10:01:57.581 strm0x7fbdcc020848 Jitter buffer starts returning normal frames (after 1 empty/lost)" [2018-04-27 10:01:57.761] [Debug] [proto.sip] unknown:0 - "10:01:57.761 strm0x7fbdcc020848 Frame lost, recovered!" [2018-04-27 10:01:57.762] [Debug] [proto.sip] unknown:0 - "10:01:57.762 strm0x7fbdcc020848 Jitter buffer starts returning normal frames (after 1 empty/lost)" [2018-04-27 10:01:57.938] [Debug] [proto.sip] unknown:0 - "10:01:57.938 strm0x7fbdcc020848 Frame lost, recovered!" [2018-04-27 10:01:57.959] [Debug] [proto.sip] unknown:0 - "10:01:57.958 strm0x7fbdcc020848 Jitter buffer starts returning normal frames (after 1 empty/lost)" [2018-04-27 10:01:58.140] [Debug] [proto.sip] unknown:0 - "10:01:58.140 strm0x7fbdcc020848 Frame lost, recovered!" [2018-04-27 10:01:58.141] [Debug] [proto.sip] unknown:0 - "10:01:58.141 strm0x7fbdcc020848 Jitter buffer starts returning normal frames (after 1 empty/lost)" [2018-04-27 10:01:58.181] [Debug] [proto.sip] unknown:0 - "10:01:58.181 pjsua_acc.c !Sending 2 bytes keep-alive packet for acc 0 to 192.168.42.200:5060" [2018-04-27 10:01:58.181] [Debug] [proto.sip] unknown:0 - "10:01:58.181 tdta0x7fbdcc028f18 Destroying txdata raw" [2018-04-27 10:01:58.321] [Debug] [proto.sip] unknown:0 - "10:01:58.321 strm0x7fbdcc020848 !Frame lost, recovered!" [2018-04-27 10:01:58.340] [Debug] [proto.sip] unknown:0 - "10:01:58.340 strm0x7fbdcc020848 Jitter buffer starts returning normal frames (after 1 empty/lost)" [2018-04-27 10:01:58.520] [Debug] [proto.sip] unknown:0 - "10:01:58.520 strm0x7fbdcc020848 Frame lost, recovered!" [2018-04-27 10:01:58.520] [Debug] [proto.sip] unknown:0 - "10:01:58.520 strm0x7fbdcc020848 Jitter buffer starts returning normal frames (after 1 empty/lost)" [2018-04-27 10:01:58.699] [Debug] [proto.sip] unknown:0 - "10:01:58.699 strm0x7fbdcc020848 Frame lost, recovered!" [2018-04-27 10:01:58.720] [Debug] [proto.sip] unknown:0 - "10:01:58.720 strm0x7fbdcc020848 Jitter buffer starts returning normal frames (after 1 empty/lost)" [2018-04-27 10:01:58.899] [Debug] [proto.sip] unknown:0 - "10:01:58.899 strm0x7fbdcc020848 Frame lost, recovered!" [2018-04-27 10:01:58.899] [Debug] [proto.sip] unknown:0 - "10:01:58.899 strm0x7fbdcc020848 Jitter buffer starts returning normal frames (after 1 empty/lost)" [2018-04-27 10:01:59.079] [Debug] [proto.sip] unknown:0 - "10:01:59.079 strm0x7fbdcc020848 Frame lost, recovered!" [2018-04-27 10:01:59.100] [Debug] [proto.sip] unknown:0 - "10:01:59.100 strm0x7fbdcc020848 Jitter buffer starts returning normal frames (after 1 empty/lost)" [2018-04-27 10:01:59.280] [Debug] [proto.sip] unknown:0 - "10:01:59.280 strm0x7fbdcc020848 Frame lost, recovered!" [2018-04-27 10:01:59.280] [Debug] [proto.sip] unknown:0 - "10:01:59.280 strm0x7fbdcc020848 Jitter buffer starts returning normal frames (after 1 empty/lost)" [2018-04-27 10:01:59.497] [Debug] [proto.sip] unknown:0 - "10:01:59.497 strm0x7fbdcc020848 Frame lost, recovered!" [2018-04-27 10:01:59.497] [Debug] [proto.sip] unknown:0 - "10:01:59.497 strm0x7fbdcc020848 Jitter buffer starts returning normal frames (after 1 empty/lost)" [2018-04-27 10:01:59.740] [Debug] [proto.sip] unknown:0 - "10:01:59.740 strm0x7fbdcc020848 Frame lost, recovered!" [2018-04-27 10:01:59.761] [Debug] [proto.sip] unknown:0 - "10:01:59.761 strm0x7fbdcc020848 Jitter buffer starts returning normal frames (after 1 empty/lost)" [2018-04-27 10:01:59.784] [Debug] [proto.sip] unknown:0 - "10:01:59.784 sip_endpoint.c !Processing incoming message: Request msg BYE/cseq=102 (rdata0x7fbdcc013ee8)" [2018-04-27 10:01:59.785] [Debug] [proto.sip] unknown:0 - "10:01:59.785 pjsua_core.c .RX 625 bytes Request msg BYE/cseq=102 (rdata0x7fbdcc013ee8) from UDP 192.168.42.200:5060: BYE sip:XJ15zaZnchCOaOh@192.168.42.48:54418;ob SIP/2.0\r Via: SIP/2.0/UDP 192.168.42.200:5060;branch=z9hG4bK1c4244e2;rport\r Max-Forwards: 70\r From: sip:*9001@pascom;tag=as02514e3d\r To: sip:XJ15zaZnchCOaOh@pascom;tag=152d75ac-6728-4e85-b8c1-01102994125a\r Call-ID: 8c1e6478-8443-40a7-b16b-813ff3cc4a8e\r CSeq: 102 BYE\r User-Agent: Asterisk PBX certified/11.6-cert17\r Proxy-Authorization: Digest username=\"XJ15zaZnchCOaOh\", realm=\"pascom\", algorithm=MD5, uri=\"sip:pascom\", nonce=\"6f9fab09\", response=\"8316cf8ac708c0709e69d5dbca4d1ad2\"\r X-Asterisk-HangupCause: Normal Clearing\r X-Asterisk-HangupCauseCode: 16\r Content-Length: 0\r \r --end msg--" [2018-04-27 10:01:59.785] [Debug] [proto.sip] unknown:0 - "10:01:59.785 dlg0x3c46578 .Received Request msg BYE/cseq=102 (rdata0x7fbdcc013ee8)" [2018-04-27 10:01:59.785] [Debug] [proto.sip] unknown:0 - "10:01:59.785 tsx0x7fbdcc01e2a8 ...Transaction created for Request msg BYE/cseq=102 (rdata0x7fbdcc013ee8)" [2018-04-27 10:01:59.785] [Debug] [proto.sip] unknown:0 - "10:01:59.785 tsx0x7fbdcc01e2a8 ..Incoming Request msg BYE/cseq=102 (rdata0x7fbdcc013ee8) in state Null" [2018-04-27 10:01:59.785] [Debug] [proto.sip] unknown:0 - "10:01:59.785 tsx0x7fbdcc01e2a8 ...State changed from Null to Trying, event=RX_MSG" [2018-04-27 10:01:59.785] [Debug] [proto.sip] unknown:0 - "10:01:59.785 dlg0x3c46578 ....Transaction tsx0x7fbdcc01e2a8 state changed to Trying" [2018-04-27 10:01:59.785] [Debug] [proto.sip] unknown:0 - "10:01:59.785 endpoint .....Response msg 200/BYE/cseq=102 (tdta0x7fbdcc028f18) created" [2018-04-27 10:01:59.785] [Debug] [proto.sip] unknown:0 - "10:01:59.785 dlg0x3c46578 ......Sending Response msg 200/BYE/cseq=102 (tdta0x7fbdcc028f18)" [2018-04-27 10:01:59.785] [Debug] [proto.sip] unknown:0 - "10:01:59.785 tsx0x7fbdcc01e2a8 ......Sending Response msg 200/BYE/cseq=102 (tdta0x7fbdcc028f18) in state Trying" [2018-04-27 10:01:59.786] [Debug] [proto.sip] unknown:0 - "10:01:59.786 pjsua_core.c .......TX 312 bytes Response msg 200/BYE/cseq=102 (tdta0x7fbdcc028f18) to UDP 192.168.42.200:5060: SIP/2.0 200 OK\r Via: SIP/2.0/UDP 192.168.42.200:5060;rport=5060;received=192.168.42.200;branch=z9hG4bK1c4244e2\r Call-ID: 8c1e6478-8443-40a7-b16b-813ff3cc4a8e\r From: <sip:*9001@pascom>;tag=as02514e3d\r To: <sip:XJ15zaZnchCOaOh@pascom>;tag=152d75ac-6728-4e85-b8c1-01102994125a\r CSeq: 102 BYE\r Content-Length: 0\r \r --end msg--" [2018-04-27 10:01:59.786] [Debug] [proto.sip] unknown:0 - "10:01:59.786 tsx0x7fbdcc01e2a8 .......State changed from Trying to Completed, event=TX_MSG" [2018-04-27 10:01:59.786] [Debug] [proto.sip] unknown:0 - "10:01:59.786 dlg0x3c46578 ........Transaction tsx0x7fbdcc01e2a8 state changed to Completed" [2018-04-27 10:01:59.786] [Debug] [proto.sip] unknown:0 - "10:01:59.786 pjsua_media.c ......Call 0: deinitializing media.." [2018-04-27 10:01:59.786] [Info] [service.MdSoftphone] unknown:0 - Removing call id 0 , now 0 calls [2018-04-27 10:01:59.786] [Debug] [proto.sip] unknown:0 - "10:01:59.786 strm0x7fbdcc020848 ........JB summary: size=7/eff=7 prefetch=0 level=2 delay (min/max/avg/dev)=90/280/187/58 ms burst (min/max/avg/dev)=2/2/2/0 frames lost=19 discard=0 empty=14" [2018-04-27 10:01:59.786] [Debug] [controller.SoftPhoneController] unknown:0 - Cleanup guarding reference to call [2018-04-27 10:01:59.786] [Debug] [proto.sip] unknown:0 - "10:01:59.786 pjsua_media.c ........Media stream call00:0 is destroyed" [2018-04-27 10:01:59.786] [Debug] [util.MdCall] unknown:0 - Destruct Call [2018-04-27 10:01:59.787] [Debug] [proto.sip] unknown:0 - "10:01:59.787 tdta0x7fbdcc025528 .....Destroying txdata Request msg ACK/cseq=15620 (tdta0x7fbdcc025528)" [2018-04-27 10:01:59.787] [Debug] [proto.sip] unknown:0 - "10:01:59.787 tdta0x3d4ce38 .....Destroying txdata Request msg INVITE/cseq=15620 (tdta0x3d4ce38)" [2018-04-27 10:01:59.787] [Debug] [proto.sip] unknown:0 - "10:01:59.787 dlg0x3c46578 ......Session count dec to 3 by mod-invite" [2018-04-27 10:01:59.788] [Info] [service.PhonecallService] unknown:0 - My phone state is available finish all calls [2018-04-27 10:01:59.813] [Info] [service.PhonecallService] unknown:0 - phonecall destroyed id 107713 [2018-04-27 10:02:00.787] [Debug] [proto.sip] unknown:0 - "10:02:00.787 pjsua_aud.c Closing sound device after idle for 1 second(s)" [2018-04-27 10:02:00.787] [Debug] [proto.sip] unknown:0 - "10:02:00.787 pjsua_aud.c .Closing pulse sound playback device and pulse sound capture device" ## Anruf beendet, zweiter Anruf ## [2018-04-27 10:02:12.222] [Debug] [service.MdSoftphone] unknown:0 - Add outbound call id -1, now 1 calls [2018-04-27 10:02:12.222] [Debug] [service.MdSoftphone] unknown:0 - Thread id mdsoftphone: threadID= QThread(0x20ff890) [2018-04-27 10:02:12.222] [Debug] [proto.sip] unknown:0 - "10:02:12.222 pjsua_call.c !Making call with acc #0 to sip:*9001@pascom" ## Keine reaktion mehr, kann den Client nur killen ##