Forseta Posted August 14, 2017 #1 Share Posted August 14, 2017 Hallo zusammen, nachdem ich schlicht nicht weiterkomme, mal die Frage an die Runde. Ich möchte unsere Überwachungslösung automatisierte Anrufe auslösen lassen über unsere Swyx Anlage. Zu diesem Zweck habe ich auf Linuxbasis mir "pjsip" installiert (verschiedene Versionen, Alte als auch Aktuelle). Immer der gleiche Fehler, die SIP Registrierung + Anwahl klappt nur ab und zu (nur ca. in 5% aller Fälle. Aber hin und wieder geht es halt doch, also wohl keine komplett falsche Konfiguration ...). Folgendes tracing zeigt mir pjsip bei ERFOLGREICHEM ausführen: Quote root@SERVER:~/tools/pjproject-2.6/pjsip-apps/bin# ./pjsua-x86_64-unknown-linux-gnu --config-file /etc/pjsip/swyx01.conf --play-file /root/pcm1644s.wav --auto-play --duration 60 --max-calls 1 sip:21@123.123.123.123 --app-log-level=6 --log-level=6 --log-file=test 11:21:49.838 os_core_unix.c !pjlib 2.6 for POSIX initialized 11:21:49.838 sip_endpoint.c .Creating endpoint instance... 11:21:49.839 pjlib .select() I/O Queue created (0xe22730) 11:21:49.839 sip_endpoint.c .Module "mod-msg-print" registered 11:21:49.839 sip_transport. .Transport manager created. 11:21:49.839 pjsua_core.c .PJSUA state changed: NULL --> CREATED 11:21:49.839 sip_endpoint.c .Module "mod-pjsua-log" registered 11:21:49.839 sip_endpoint.c .Module "mod-tsx-layer" registered 11:21:49.839 sip_endpoint.c .Module "mod-stateful-util" registered 11:21:49.839 sip_endpoint.c .Module "mod-ua" registered 11:21:49.839 sip_endpoint.c .Module "mod-100rel" registered 11:21:49.840 sip_endpoint.c .Module "mod-pjsua" registered 11:21:49.840 sip_endpoint.c .Module "mod-invite" registered 11:21:49.842 alsa_dev.c ..ALSA driver found 0 devices 11:21:49.842 alsa_dev.c ..ALSA initialized 11:21:49.842 pjlib ..select() I/O Queue created (0xe34448) 11:21:49.843 conference.c ..Creating conference bridge with 254 ports 11:21:49.843 Master/sound ..Using delay buffer with WSOLA. 11:21:49.848 sip_endpoint.c .Module "mod-evsub" registered 11:21:49.848 sip_endpoint.c .Module "mod-presence" registered 11:21:49.848 evsub.c .Event pkg "presence" registered by mod-presence 11:21:49.848 sip_endpoint.c .Module "mod-mwi" registered 11:21:49.849 evsub.c .Event pkg "message-summary" registered by mod-mwi 11:21:49.849 sip_endpoint.c .Module "mod-refer" registered 11:21:49.849 evsub.c .Event pkg "refer" registered by mod-refer 11:21:49.849 sip_endpoint.c .Module "mod-pjsua-pres" registered 11:21:49.849 sip_endpoint.c .Module "mod-pjsua-im" registered 11:21:49.849 sip_endpoint.c .Module "mod-pjsua-options" registered 11:21:49.849 pjsua_core.c .1 SIP worker threads created 11:21:49.849 pjsua_core.c .pjsua version 2.6 for Linux-4.4.0.89/x86_64/glibc-2.19 initialized 11:21:49.850 pjsua_core.c .PJSUA state changed: CREATED --> INIT 11:21:49.850 sip_endpoint.c Module "mod-default-handler" registered 11:21:49.850 pjsua_aud.c Creating file player: /root/pcm1644s.wav.. 11:21:49.850 wav_player.c .File player '/root/pcm1644s.wav' created: samp.rate=44100, ch=2, bufsize=4KB, filesize=1179KB 11:21:49.850 resample.c .resample created: high qualiy, large filter, in/out rate=44100/16000 11:21:49.850 resample.c .resample created: high qualiy, large filter, in/out rate=16000/44100 11:21:49.850 pjsua_aud.c .Player created, id=0, slot=1 11:21:49.850 pjsua_core.c SIP UDP socket reachable at 10.10.10.10:5060 11:21:49.851 udp0xe474d0 SIP UDP transport started, published address is 10.10.10.10:5060 11:21:49.851 pjsua_acc.c Adding account: id=<sip:10.10.10.10:5060> 11:21:49.851 pjsua_acc.c .Account <sip:10.10.10.10:5060> added with id 0 11:21:49.851 pjsua_acc.c Modifying account 0 11:21:49.851 pjsua_acc.c Acc 0: setting online status to 1.. 11:21:49.851 tcptp:5060 SIP TCP listener ready for incoming connections at 10.10.10.10:5060 11:21:49.851 pjsua_acc.c Adding account: id=<sip:10.10.10.10:5060;transport=TCP> 11:21:49.851 pjsua_acc.c .Account <sip:10.10.10.10:5060;transport=TCP> added with id 1 11:21:49.851 pjsua_acc.c Modifying account 1 11:21:49.852 pjsua_acc.c Acc 1: setting online status to 1.. 11:21:49.852 pjsua_acc.c Adding account: id=sip:user@123.123.123.123 11:21:49.852 pjsua_acc.c .Account sip:user@123.123.123.123 added with id 2 11:21:49.852 pjsua_acc.c .Acc 2: setting registration.. 11:21:49.852 endpoint ..Request msg REGISTER/cseq=61523 (tdta0xe56790) created. 11:21:49.852 tsx0xe587f8 ...Transaction created for Request msg REGISTER/cseq=61524 (tdta0xe56790) 11:21:49.852 tsx0xe587f8 ..Sending Request msg REGISTER/cseq=61524 (tdta0xe56790) in state Null 11:21:49.852 sip_resolve.c ...Target '123.123.123.123:0' type=Unspecified resolved to '123.123.123.123:5060' type=UDP (UDP transport) 11:21:49.852 pjsua_core.c ...TX 575 bytes Request msg REGISTER/cseq=61524 (tdta0xe56790) to UDP 123.123.123.123:5060: REGISTER sip:123.123.123.123 SIP/2.0 Via: SIP/2.0/UDP 10.10.10.10:5060;rport;branch=z9hG4bKPjj8j9QNUkTS90Hw598WkYPd6fnRqCewH. Route: <sip:123.123.123.123;lr> Max-Forwards: 70 From: <sip:user@123.123.123.123>;tag=Y5gMwqvP6QFUxqo9bP375pJxIYWqpO6i To: <sip:user@123.123.123.123> Call-ID: uSX77KoKdBE7EhaFd0Hw4UuXY8qdyiH6 CSeq: 61524 REGISTER User-Agent: PJSUA v2.6 Linux-4.4.0.89/x86_64/glibc-2.19 Contact: <sip:user@10.10.10.10:5060;ob> Expires: 300 Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Content-Length: 0 --end msg-- 11:21:49.853 tsx0xe587f8 ...State changed from Null to Calling, event=TX_MSG 11:21:49.853 pjsua_acc.c ..Acc 2: Registration sent 11:21:49.853 pjsua_acc.c Acc 2: setting online status to 1.. 11:21:49.853 pjsua_pres.c Adding buddy: sip:21@123.123.123.123 11:21:49.853 pjsua_pres.c .Buddy 0 added. 11:21:49.853 pjsua_pres.c ..Buddy 0: updating presence.. 11:21:49.853 pjsua_aud.c Setting null sound device.. 11:21:49.854 pjsua_app.c .Turning sound device ON 11:21:49.854 pjsua_aud.c .Opening null sound device.. 11:21:49.854 pjsua_core.c PJSUA state changed: INIT --> STARTING 11:21:49.854 sip_endpoint.c .Module "mod-unsolicited-mwi" registered 11:21:49.854 pjsua_core.c .PJSUA state changed: STARTING --> RUNNING 11:21:49.854 main.c Ready: Success 11:21:49.854 pjsua_call.c Making call with acc #2 to sip:21@123.123.123.123 11:21:49.854 dlg0xe5c4b8 .UAC dialog created 11:21:49.854 dlg0xe5c4b8 ..Session count inc to 2 by mod-pjsua 11:21:49.855 pjsua_media.c .Call 0: initializing media.. 11:21:49.855 pjsua_media.c ..RTP socket reachable at 10.10.10.10:4000 11:21:49.855 pjsua_media.c ..RTCP socket reachable at 10.10.10.10:4001 11:21:49.855 pjsua_media.c ..Media index 0 selected for audio call 0 11:21:49.855 pjsua_media.c ..Call 0: media transport initialization complete: Success 11:21:49.855 dlg0xe5c4b8 ..Session count dec to 2 by mod-pjsua 11:21:49.855 dlg0xe5c4b8 .Module mod-invite added as dialog usage, data=0xe60cd8 11:21:49.855 dlg0xe5c4b8 ..Session count inc to 4 by mod-invite 11:21:49.855 dlg0xe5c4b8 .Module mod-100rel added as dialog usage, data=0xe64400 11:21:49.855 dlg0xe5c4b8 .100rel module attached 11:21:49.855 inv0xe5c4b8 .UAC invite session created for dialog dlg0xe5c4b8 11:21:49.856 endpoint .Request msg INVITE/cseq=7540 (tdta0xe64960) created. 11:21:49.856 inv0xe5c4b8 ..Sending Request msg INVITE/cseq=7540 (tdta0xe64960) 11:21:49.856 dlg0xe5c4b8 ...Sending Request msg INVITE/cseq=7540 (tdta0xe64960) 11:21:49.856 tsx0xe67978 ....Transaction created for Request msg INVITE/cseq=7539 (tdta0xe64960) 11:21:49.856 tsx0xe67978 ...Sending Request msg INVITE/cseq=7539 (tdta0xe64960) in state Null 11:21:49.856 sip_resolve.c ....Target '123.123.123.123:0' type=Unspecified resolved to '123.123.123.123:5060' type=UDP (UDP transport) 11:21:49.856 pjsua_core.c ....TX 1141 bytes Request msg INVITE/cseq=7539 (tdta0xe64960) to UDP 123.123.123.123:5060: INVITE sip:21@123.123.123.123 SIP/2.0 Via: SIP/2.0/UDP 10.10.10.10:5060;rport;branch=z9hG4bKPjotsiQzc5PHGrNDZogOXhfG30V0KXFqS0 Max-Forwards: 70 From: sip:user@123.123.123.123;tag=Q3fySmpjRYjoWRG1vA6F8WEdKFkjDfmk To: sip:21@123.123.123.123 Contact: <sip:user@10.10.10.10:5060;ob> Call-ID: D5pjqappzfNQyFstCWeWca.QT1JY5ydx CSeq: 7539 INVITE Route: <sip:123.123.123.123;lr> Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Supported: replaces, 100rel, timer, norefersub Session-Expires: 1800 Min-SE: 90 User-Agent: PJSUA v2.6 Linux-4.4.0.89/x86_64/glibc-2.19 Content-Type: application/sdp Content-Length: 473 v=0 o=- 3711345709 3711345709 IN IP4 10.10.10.10 s=pjmedia b=AS:84 t=0 0 a=X-nat:0 m=audio 4000 RTP/AVP 98 97 99 104 3 0 8 9 96 c=IN IP4 10.10.10.10 b=TIAS:64000 a=rtcp:4001 IN IP4 10.10.10.10 a=sendrecv a=rtpmap:98 speex/16000 a=rtpmap:97 speex/8000 a=rtpmap:99 speex/32000 a=rtpmap:104 iLBC/8000 a=fmtp:104 mode=30 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:9 G722/8000 a=rtpmap:96 telephone-event/8000 a=fmtp:96 0-16 --end msg-- 11:21:49.858 tsx0xe67978 ....State changed from Null to Calling, event=TX_MSG 11:21:49.859 dlg0xe5c4b8 .....Transaction tsx0xe67978 state changed to Calling 11:21:49.859 pjsua_app.c .......Call 0 state changed to CALLING >>>> Account list: [ 0] <sip:10.10.10.10:5060>: does not register Online status: Online [ 1] <sip:10.10.10.10:5060;transport=TCP>: does not register Online status: Online *[ 2] sip:user@123.123.123.123: 100/In Progress (expires=0) Online status: Online Buddy list: [ 1] <?> sip:21@123.123.123.123 +=============================================================================+ | Call Commands: | Buddy, IM & Presence: | Account: | | | | | | m Make new call | +b Add new buddy .| +a Add new accnt | | M Make multiple calls | -b Delete buddy | -a Delete accnt. | | a Answer call | i Send IM | !a Modify accnt. | | h Hangup call (ha=all) | s Subscribe presence | rr (Re-)register | | H Hold call | u Unsubscribe presence | ru Unregister | | v re-inVite (release hold) | t ToGgle Online status | > Cycle next ac.| | U send UPDATE | T Set online status | < Cycle prev ac.| | ],[ Select next/prev call +--------------------------+-------------------+ | x Xfer call | Media Commands: | Status & Config: | | X Xfer with Replaces | | | | # Send RFC 2833 DTMF | cl List ports | d Dump status | | * Send DTMF with INFO | cc Connect port | dd Dump detailed | | dq Dump curr. call quality | cd Disconnect port | dc Dump config | | | V Adjust audio Volume | f Save config | | S Send arbitrary REQUEST | Cp Codec priorities | | +-----------------------------------------------------------------------------+ | q QUIT L ReLoad sleep MS echo [0|1|txt] n: detect NAT type | +=============================================================================+ You have 1 active call Current call id=0 to sip:21@123.123.123.123 [CALLING] >>> 11:21:49.859 sip_endpoint.c !Processing incoming message: Response msg 100/REGISTER/cseq=61524 (rdata0xe515f8) 11:21:49.861 pjsua_core.c .RX 434 bytes Response msg 100/REGISTER/cseq=61524 (rdata0xe515f8) from UDP 123.123.123.123:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.10.10.10:5060;rport=5060;branch=z9hG4bKPjj8j9QNUkTS90Hw598WkYPd6fnRqCewH. To: <sip:user@123.123.123.123> From: <sip:user@123.123.123.123>;tag=Y5gMwqvP6QFUxqo9bP375pJxIYWqpO6i Call-ID: uSX77KoKdBE7EhaFd0Hw4UuXY8qdyiH6 CSeq: 61524 REGISTER Allow: REGISTER, INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, INFO, SUBSCRIBE, UPDATE User-Agent: Swyx IpPbxSrv/10.40.0.304 Content-Length: 0 --end msg-- 11:21:49.861 tsx0xe587f8 .Incoming Response msg 100/REGISTER/cseq=61524 (rdata0xe515f8) in state Calling 11:21:49.861 tsx0xe587f8 ..State changed from Calling to Proceeding, event=RX_MSG 11:21:49.861 sip_endpoint.c Processing incoming message: Response msg 200/REGISTER/cseq=61524 (rdata0x7f7b940008e8) 11:21:49.861 pjsua_core.c .RX 536 bytes Response msg 200/REGISTER/cseq=61524 (rdata0x7f7b940008e8) from UDP 123.123.123.123:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.10.10.10:5060;rport=5060;branch=z9hG4bKPjj8j9QNUkTS90Hw598WkYPd6fnRqCewH. Contact: <sip:user@10.10.10.10:5060;ob>;expires=120 To: <sip:user@123.123.123.123>;tag=2e657f0f From: <sip:user@123.123.123.123>;tag=Y5gMwqvP6QFUxqo9bP375pJxIYWqpO6i Call-ID: uSX77KoKdBE7EhaFd0Hw4UuXY8qdyiH6 CSeq: 61524 REGISTER Allow: REGISTER, INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, INFO, SUBSCRIBE, UPDATE Date: Thu, 10 Aug 2017 09:21:49 GMT User-Agent: Swyx IpPbxSrv/10.40.0.304 Content-Length: 0 --end msg-- 11:21:49.861 tsx0xe587f8 .Incoming Response msg 200/REGISTER/cseq=61524 (rdata0x7f7b940008e8) in state Proceeding 11:21:49.861 tsx0xe587f8 ..State changed from Proceeding to Completed, event=RX_MSG 11:21:49.861 pjsua_acc.c ....SIP outbound status for acc 2 is not active 11:21:49.861 pjsua_acc.c ....sip:user@123.123.123.123: registration success, status=200 (OK), will re-register in 120 seconds 11:21:49.861 pjsua_acc.c ....Keep-alive timer started for acc 2, destination:123.123.123.123:5060, interval:15s 11:21:49.862 sip_endpoint.c Processing incoming message: Response msg 100/INVITE/cseq=7539 (rdata0x7f7b940008e8) 11:21:49.862 pjsua_core.c .RX 427 bytes Response msg 100/INVITE/cseq=7539 (rdata0x7f7b940008e8) from UDP 123.123.123.123:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.10.10.10:5060;rport=5060;branch=z9hG4bKPjotsiQzc5PHGrNDZogOXhfG30V0KXFqS0 To: <sip:21@123.123.123.123> From: <sip:user@123.123.123.123>;tag=Q3fySmpjRYjoWRG1vA6F8WEdKFkjDfmk Call-ID: D5pjqappzfNQyFstCWeWca.QT1JY5ydx CSeq: 7539 INVITE Allow: REGISTER, INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, INFO, SUBSCRIBE, UPDATE User-Agent: Swyx IpPbxSrv/10.40.0.304 Content-Length: 0 --end msg-- 11:21:49.862 tsx0xe67978 .Incoming Response msg 100/INVITE/cseq=7539 (rdata0x7f7b940008e8) in state Calling 11:21:49.862 tsx0xe67978 ..State changed from Calling to Proceeding, event=RX_MSG 11:21:49.862 dlg0xe5c4b8 ...Received Response msg 100/INVITE/cseq=7539 (rdata0x7f7b940008e8) 11:21:49.862 dlg0xe5c4b8 ...Transaction tsx0xe67978 state changed to Proceeding 11:21:50.532 sip_endpoint.c Processing incoming message: Response msg 180/INVITE/cseq=7539 (rdata0x7f7b940008e8) 11:21:50.532 pjsua_core.c .RX 685 bytes Response msg 180/INVITE/cseq=7539 (rdata0x7f7b940008e8) from UDP 123.123.123.123:5060: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.10.10.10:5060;rport=5060;branch=z9hG4bKPjotsiQzc5PHGrNDZogOXhfG30V0KXFqS0 Contact: <sip:123.123.123.123:5060;transport=udp> To: "John Doe"<sip:21@123.123.123.123>;tag=69132c66 From: <sip:user@123.123.123.123>;tag=Q3fySmpjRYjoWRG1vA6F8WEdKFkjDfmk Call-ID: D5pjqappzfNQyFstCWeWca.QT1JY5ydx CSeq: 7539 INVITE Allow: REGISTER, INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, INFO, SUBSCRIBE, UPDATE User-Agent: Swyx IpPbxSrv/10.40.0.304 X-IPPBXAlertType: 0 X-IPPBXRedirected: false X-IPPBXCalledNumber: 21 X-IPPBXCalledName: John Doe X-IPPBXServerCallId: 954394 X-IPPBXServerCallContext: 382ya0hb6053 Content-Length: 0 --end msg-- 11:21:50.532 tsx0xe67978 .Incoming Response msg 180/INVITE/cseq=7539 (rdata0x7f7b940008e8) in state Proceeding 11:21:50.532 tsx0xe67978 ..State changed from Proceeding to Proceeding, event=RX_MSG 11:21:50.533 dlg0xe5c4b8 ...Received Response msg 180/INVITE/cseq=7539 (rdata0x7f7b940008e8) 11:21:50.533 dlg0xe5c4b8 ....Route-set updated 11:21:50.533 dlg0xe5c4b8 ...Transaction tsx0xe67978 state changed to Proceeding 11:21:50.533 pjsua_aud.c .....Conf connect: 2 --> 0 11:21:50.533 conference.c ......Port 2 (ringback) transmitting to port 0 (Master/sound) 11:21:50.533 pjsua_app.c .....Call 0 state changed to EARLY (180 Ringing) 11:21:54.781 sip_endpoint.c Processing incoming message: Response msg 200/INVITE/cseq=7539 (rdata0x7f7b940008e8) 11:21:54.781 pjsua_core.c .RX 925 bytes Response msg 200/INVITE/cseq=7539 (rdata0x7f7b940008e8) from UDP 123.123.123.123:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.10.10.10:5060;rport=5060;branch=z9hG4bKPjotsiQzc5PHGrNDZogOXhfG30V0KXFqS0 Require: timer Contact: <sip:123.123.123.123:5060;transport=udp> To: "John Doe"<sip:21@123.123.123.123>;tag=69132c66 From: <sip:user@123.123.123.123>;tag=Q3fySmpjRYjoWRG1vA6F8WEdKFkjDfmk Call-ID: D5pjqappzfNQyFstCWeWca.QT1JY5ydx CSeq: 7539 INVITE Session-Expires: 1800;refresher=uas Min-SE: 90 Allow: REGISTER, INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, INFO, SUBSCRIBE, UPDATE Content-Type: application/sdp Supported: timer User-Agent: Swyx IpPbxSrv/10.40.0.304 X-IPPBXServerCallId: 954394 X-IPPBXServerCallContext: 382ya0hb6053 X-IPPBXRedirected: false X-IPPBXCalledNumber: 21 X-IPPBXCalledName: John Doe Content-Length: 150 v=0 o=- 3315842696 1 IN IP4 10.240.49.205 s=Swyx PhoneMgr c=IN IP4 10.240.49.205 t=0 0 m=audio 5010 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=ptime:20 --end msg-- 11:21:54.781 tsx0xe67978 .Incoming Response msg 200/INVITE/cseq=7539 (rdata0x7f7b940008e8) in state Proceeding 11:21:54.781 tsx0xe67978 ..State changed from Proceeding to Terminated, event=RX_MSG 11:21:54.781 dlg0xe5c4b8 ...Received Response msg 200/INVITE/cseq=7539 (rdata0x7f7b940008e8) 11:21:54.781 dlg0xe5c4b8 ....Route-set updated 11:21:54.781 dlg0xe5c4b8 ....Route-set frozen 11:21:54.781 dlg0xe5c4b8 ...Transaction tsx0xe67978 state changed to Terminated 11:21:54.781 pjsua_app.c .....Call 0 state changed to CONNECTING 11:21:54.781 inv0xe5c4b8 ....Got SDP answer in Response msg 200/INVITE/cseq=7539 (rdata0x7f7b940008e8) 11:21:54.781 inv0xe5c4b8 ....SDP negotiation done, status=0 11:21:54.781 pjsua_call.c .....Call 0: remote NAT type is 0 (Unknown) 11:21:54.781 pjsua_media.c .....Call 0: updating media.. 11:21:54.781 pjsua_aud.c ......Audio channel update.. 11:21:54.782 strm0x7f7b9400 .......VAD temporarily disabled 11:21:54.782 rtp.c .......pjmedia_rtp_session_init: ses=0x7f7b94006a44, default_pt=0, ssrc=0x4a6eebb7 11:21:54.782 rtp.c .......pjmedia_rtp_session_init: ses=0x7f7b940070c4, default_pt=0, ssrc=0x4a6eebb7 11:21:54.782 stream.c .......Stream strm0x7f7b940043a8 created 11:21:54.782 strm0x7f7b9400 .......Encoder stream started 11:21:54.782 strm0x7f7b9400 .......Decoder stream started 11:21:54.782 resample.c .......resample created: high qualiy, large filter, in/out rate=8000/16000 11:21:54.782 resample.c .......resample created: high qualiy, large filter, in/out rate=16000/8000 11:21:54.782 pjsua_media.c ......Audio updated, stream #0: PCMU (sendrecv) 11:21:54.782 pjsua_app.c .....Call 0 media 0 [type=audio], status is Active 11:21:54.782 pjsua_aud.c .....Conf disconnect: 2 -x- 0 11:21:54.782 conference.c ......Port 2 (ringback) stop transmitting to port 0 (Master/sound) 11:21:54.782 pjsua_aud.c .....Conf connect: 1 --> 4 11:21:54.782 conference.c ......Port 1 (/root/pcm1644s.wav) transmitting to port 4 (sip:21@123.123.123.123) 11:21:54.782 inv0xe5c4b8 ....Received Response msg 200/INVITE/cseq=7539 (rdata0x7f7b940008e8), sending ACK 11:21:54.782 endpoint ....Request msg ACK/cseq=7539 (tdta0x7f7b94008ec0) created. 11:21:54.782 dlg0xe5c4b8 .....Sending Request msg ACK/cseq=7539 (tdta0x7f7b94008ec0) 11:21:54.782 sip_resolve.c .....Target '123.123.123.123:5060' type=UDP resolved to '123.123.123.123:5060' type=UDP (UDP transport) 11:21:54.782 pjsua_core.c .....TX 345 bytes Request msg ACK/cseq=7539 (tdta0x7f7b94008ec0) to UDP 123.123.123.123:5060: ACK sip:123.123.123.123:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.10.10.10:5060;rport;branch=z9hG4bKPjHYiCDO0pqrmpED9.lkeKxWLE4EOyoHMh Max-Forwards: 70 From: sip:user@123.123.123.123;tag=Q3fySmpjRYjoWRG1vA6F8WEdKFkjDfmk To: sip:21@123.123.123.123;tag=69132c66 Call-ID: D5pjqappzfNQyFstCWeWca.QT1JY5ydx CSeq: 7539 ACK Content-Length: 0 --end msg-- 11:21:54.782 pjsua_app.c .....Call 0 state changed to CONFIRMED 11:21:54.783 tsx0xe67978 Timeout timer event 11:21:54.783 tsx0xe67978 .State changed from Terminated to Destroyed, event=TIMER 11:21:54.783 tsx0xe67978 Transaction destroyed! 11:21:54.794 strm0x7f7b9400 !Start talksprut.. 11:21:54.862 tsx0xe587f8 !Timeout timer event 11:21:54.862 tsx0xe587f8 .State changed from Completed to Terminated, event=TIMER 11:21:54.862 tsx0xe587f8 Timeout timer event 11:21:54.862 tsx0xe587f8 .State changed from Terminated to Destroyed, event=TIMER 11:21:54.862 tdta0xe56790 ..Destroying txdata Request msg REGISTER/cseq=61524 (tdta0xe56790) 11:21:54.862 tsx0xe587f8 Transaction destroyed! 11:21:55.033 strm0x7f7b9400 !RTP status: badpt=0, badssrc=0, dup=0, outorder=-1, probation=-1, restart=0 11:21:55.053 strm0x7f7b9400 RTP status: badpt=0, badssrc=0, dup=0, outorder=0, probation=-1, restart=0 11:21:55.414 strm0x7f7b9400 !VAD re-enabled 11:21:55.414 silencedet.c Starting talk burst (level=15555 threshold=1000) 11:21:56.586 sip_endpoint.c !Processing incoming message: Request msg BYE/cseq=1 (rdata0x7f7b940008e8) 11:21:56.586 pjsua_core.c .RX 557 bytes Request msg BYE/cseq=1 (rdata0x7f7b940008e8) from UDP 123.123.123.123:5060: BYE sip:user@10.10.10.10:5060;ob;transport=udp SIP/2.0 Via: SIP/2.0/UDP 123.123.123.123:5060;branch=z9hG4bK-d8754z-d4624a3cf5369252-1---d8754z-;rport Max-Forwards: 70 Contact: <sip:21@123.123.123.123:5060;transport=udp> To: <sip:user@123.123.123.123>;tag=Q3fySmpjRYjoWRG1vA6F8WEdKFkjDfmk From: <sip:21@123.123.123.123>;tag=69132c66 Call-ID: D5pjqappzfNQyFstCWeWca.QT1JY5ydx CSeq: 1 BYE Allow: REGISTER, INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, INFO, SUBSCRIBE, UPDATE Supported: timer User-Agent: Swyx IpPbxSrv/10.40.0.304 Content-Length: 0 --end msg-- 11:21:56.586 dlg0xe5c4b8 .Received Request msg BYE/cseq=1 (rdata0x7f7b940008e8) 11:21:56.586 tsx0x7f7b9400b ...Transaction created for Request msg BYE/cseq=1 (rdata0x7f7b940008e8) 11:21:56.587 tsx0x7f7b9400b ..Incoming Request msg BYE/cseq=1 (rdata0x7f7b940008e8) in state Null 11:21:56.587 tsx0x7f7b9400b ...State changed from Null to Trying, event=RX_MSG 11:21:56.587 dlg0xe5c4b8 ....Transaction tsx0x7f7b9400bec8 state changed to Trying 11:21:56.587 endpoint .....Response msg 200/BYE/cseq=1 (tdta0x7f7b9400ca50) created 11:21:56.587 dlg0xe5c4b8 ......Sending Response msg 200/BYE/cseq=1 (tdta0x7f7b9400ca50) 11:21:56.587 tsx0x7f7b9400b ......Sending Response msg 200/BYE/cseq=1 (tdta0x7f7b9400ca50) in state Trying 11:21:56.587 pjsua_core.c .......TX 324 bytes Response msg 200/BYE/cseq=1 (tdta0x7f7b9400ca50) to UDP 123.123.123.123:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 123.123.123.123:5060;rport=5060;received=123.123.123.123;branch=z9hG4bK-d8754z-d4624a3cf5369252-1---d8754z- Call-ID: D5pjqappzfNQyFstCWeWca.QT1JY5ydx From: <sip:21@123.123.123.123>;tag=69132c66 To: <sip:user@123.123.123.123>;tag=Q3fySmpjRYjoWRG1vA6F8WEdKFkjDfmk CSeq: 1 BYE Content-Length: 0 --end msg-- 11:21:56.588 tsx0x7f7b9400b .......State changed from Trying to Completed, event=TX_MSG 11:21:56.588 dlg0xe5c4b8 ........Transaction tsx0x7f7b9400bec8 state changed to Completed 11:21:56.588 pjsua_app.c ......Call 0 is DISCONNECTED [reason=200 (Normal call clearing)] 11:21:56.589 pjsua_app.c ......Call 0 disconnected, dumping media stats.. 11:21:56.589 pjsua_app_comm ...... [DISCONNCTD] To: sip:21@123.123.123.123;tag=69132c66 Call time: 00h:00m:01s, 1st res in 679 ms, conn in 4928ms #0 audio PCMU @8kHz, sendrecv, peer=10.240.49.205:5010 SRTP status: Not active Crypto-suite: RX pt=0, last update:00h:00m:01.355s ago total 77pkt 12.3KB (15.4KB +IP hdr) @avg=54.5Kbps/68.1Kbps pkt loss=1 (1.3%), discrd=1 (1.3%), dup=0 (0.0%), reord=0 (0.0%) (msec) min avg max last dev loss period: 20.000 20.000 20.000 20.000 0.000 jitter : 0.000 0.277 0.625 0.250 0.164 TX pt=0, ptime=20, last update:never total 90pkt 14.4KB (18.0KB +IP hdr) @avg=63.7Kbps/79.6Kbps pkt loss=0 (0.0%), dup=0 (0.0%), reorder=0 (0.0%) (msec) min avg max last dev loss period: 0.000 0.000 0.000 0.000 0.000 jitter : 0.000 0.000 0.000 0.000 0.000 RTT msec : 0.000 0.000 0.000 0.000 0.000 11:21:56.590 pjsua_media.c ......Call 0: deinitializing media.. 11:21:56.591 strm0x7f7b9400 ........JB summary: size=50/eff=50 prefetch=0 level=0 delay (min/max/avg/dev)=0/0/0/0 ms burst (min/max/avg/dev)=0/0/0/0 frames lost=0 discard=104 empty=0 11:21:56.591 pjsua_media.c ........Media stream call00:0 is destroyed 11:21:56.591 tdta0x7f7b9400 .....Destroying txdata Request msg ACK/cseq=7539 (tdta0x7f7b94008ec0) 11:21:56.592 tdta0xe64960 .....Destroying txdata Request msg INVITE/cseq=7539 (tdta0xe64960) 11:21:56.592 dlg0xe5c4b8 ......Session count dec to 3 by mod-invite 11:21:57.591 pjsua_aud.c Closing sound device after idle for 1 second(s) 11:21:57.591 pjsua_app.c .Turning sound device OFF 11:21:57.591 pjsua_aud.c .Closing null sound device.. Cannot switch back to console from file redirection 11:21:59.201 pjsua_core.c !Shutting down, flags=0... 11:21:59.201 pjsua_core.c PJSUA state changed: RUNNING --> CLOSING 11:21:59.210 pjsua_call.c .Hangup all calls.. 11:21:59.210 pjsua_media.c .Call 0: deinitializing media.. 11:21:59.210 pjsua_pres.c .Shutting down presence.. 11:21:59.210 pjsua_acc.c .Acc 2: setting unregistration.. 11:21:59.210 endpoint ..Request msg REGISTER/cseq=61524 (tdta0xe5b0c0) created. 11:21:59.210 tsx0xe611d8 ...Transaction created for Request msg REGISTER/cseq=61525 (tdta0xe5b0c0) 11:21:59.210 tsx0xe611d8 ..Sending Request msg REGISTER/cseq=61525 (tdta0xe5b0c0) in state Null 11:21:59.210 sip_resolve.c ...Target '123.123.123.123:0' type=Unspecified resolved to '123.123.123.123:5060' type=UDP (UDP transport) 11:21:59.210 pjsua_core.c ...TX 475 bytes Request msg REGISTER/cseq=61525 (tdta0xe5b0c0) to UDP 123.123.123.123:5060: REGISTER sip:123.123.123.123 SIP/2.0 Via: SIP/2.0/UDP 10.10.10.10:5060;rport;branch=z9hG4bKPjnZmiUlpg7oHg4jVyQh9qAX0DqVhEa.Hh Route: <sip:123.123.123.123;lr> Max-Forwards: 70 From: <sip:user@123.123.123.123>;tag=lmfNEm2fQXauIj9uIhV7egmu9v6svfCg To: <sip:user@123.123.123.123> Call-ID: uSX77KoKdBE7EhaFd0Hw4UuXY8qdyiH6 CSeq: 61525 REGISTER User-Agent: PJSUA v2.6 Linux-4.4.0.89/x86_64/glibc-2.19 Contact: <sip:user@10.10.10.10:5060;ob> Expires: 0 Content-Length: 0 --end msg-- 11:21:59.210 tsx0xe611d8 ...State changed from Null to Calling, event=TX_MSG 11:21:59.210 pjsua_acc.c ..Acc 2: Unregistration sent 11:21:59.212 sip_endpoint.c .Processing incoming message: Response msg 200/REGISTER/cseq=61525 (rdata0x7f7b940008e8) 11:21:59.212 pjsua_core.c ..RX 534 bytes Response msg 200/REGISTER/cseq=61525 (rdata0x7f7b940008e8) from UDP 123.123.123.123:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.10.10.10:5060;rport=5060;branch=z9hG4bKPjnZmiUlpg7oHg4jVyQh9qAX0DqVhEa.Hh Contact: <sip:user@10.10.10.10:5060;ob>;expires=0 To: <sip:user@123.123.123.123>;tag=0774ca18 From: <sip:user@123.123.123.123>;tag=lmfNEm2fQXauIj9uIhV7egmu9v6svfCg Call-ID: uSX77KoKdBE7EhaFd0Hw4UuXY8qdyiH6 CSeq: 61525 REGISTER Allow: REGISTER, INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, INFO, SUBSCRIBE, UPDATE Date: Thu, 10 Aug 2017 09:21:59 GMT User-Agent: Swyx IpPbxSrv/10.40.0.304 Content-Length: 0 --end msg-- 11:21:59.212 tsx0xe611d8 ..Incoming Response msg 200/REGISTER/cseq=61525 (rdata0x7f7b940008e8) in state Calling 11:21:59.212 tsx0xe611d8 ...State changed from Calling to Completed, event=RX_MSG 11:21:59.212 pjsua_acc.c .....sip:user@123.123.123.123: unregistration success 11:22:00.212 pjsua_core.c .Destroying... 11:22:00.212 pjsua_media.c .Shutting down media.. 11:22:00.575 sip_endpoint.c .Destroying endpoing instance.. 11:22:00.575 sip_transactio .Stopping transaction layer module 11:22:00.575 tsx0x7f7b9400b .Request to terminate transaction 11:22:00.576 tsx0x7f7b9400b ..State changed from Completed to Terminated, event=USER 11:22:00.576 dlg0xe5c4b8 ...Transaction tsx0x7f7b9400bec8 state changed to Terminated 11:22:00.576 dlg0xe5c4b8 ....Dialog destroyed 11:22:00.576 tdta0x7f7b9400 .Destroying txdata Response msg 200/BYE/cseq=1 (tdta0x7f7b9400ca50) 11:22:00.576 tsx0x7f7b9400b .Transaction destroyed! 11:22:00.576 tsx0xe611d8 .Request to terminate transaction 11:22:00.576 tsx0xe611d8 ..State changed from Completed to Terminated, event=USER 11:22:00.576 tdta0xe5b0c0 .Destroying txdata Request msg REGISTER/cseq=61525 (tdta0xe5b0c0) 11:22:00.576 tsx0xe611d8 .Transaction destroyed! 11:22:00.576 sip_transactio .Stopped transaction layer module 11:22:00.577 sip_endpoint.c .Module "mod-default-handler" unregistered 11:22:00.577 sip_endpoint.c .Module "mod-unsolicited-mwi" unregistered 11:22:00.577 sip_endpoint.c .Module "mod-pjsua-options" unregistered 11:22:00.577 sip_endpoint.c .Module "mod-pjsua-im" unregistered 11:22:00.577 sip_endpoint.c .Module "mod-pjsua-pres" unregistered 11:22:00.577 sip_endpoint.c .Module "mod-pjsua" unregistered 11:22:00.578 sip_endpoint.c .Module "mod-stateful-util" unregistered 11:22:00.578 sip_endpoint.c .Module "mod-refer" unregistered 11:22:00.578 sip_endpoint.c .Module "mod-mwi" unregistered 11:22:00.578 sip_endpoint.c .Module "mod-presence" unregistered 11:22:00.578 sip_endpoint.c .Module "mod-evsub" unregistered 11:22:00.578 sip_endpoint.c .Module "mod-invite" unregistered 11:22:00.578 sip_endpoint.c .Module "mod-100rel" unregistered 11:22:00.578 sip_endpoint.c .Module "mod-ua" unregistered 11:22:00.578 sip_transactio .Transaction layer module destroyed 11:22:00.578 sip_endpoint.c .Module "mod-tsx-layer" unregistered 11:22:00.578 sip_endpoint.c .Module "mod-msg-print" unregistered 11:22:00.578 sip_endpoint.c .Module "mod-pjsua-log" unregistered 11:22:00.579 sip_transport. .Destroying transport manager 11:22:00.580 udp0xe474d0 .SIP UDP transport destroyed 11:22:00.580 tcptp:5060 .SIP TCP transport destroyed 11:22:00.580 sip_endpoint.c .Endpoint 0xe17998 destroyed 11:22:00.580 pcm1644s.wav .Pool is not released by application, releasing now 11:22:00.580 pjsua_core.c .PJSUA state changed: CLOSING --> NULL 11:22:00.580 pjsua_core.c .PJSUA destroyed... Folgendes tracing zeigt mir pjsip bei FEHLERHAFTEN ausführen: Quote root@SERVER:~/tools/pjproject-2.6/pjsip-apps/bin# ./pjsua-x86_64-unknown-linux-gnu --config-file /etc/pjsip/swyx01.conf --play-file /root/pcm1644s.wav --auto-play --duration 60 --max-calls 1 sip:21@123.123.123.123 --app-log-level=6 --log-level=6 --log-file=test 11:29:35.021 os_core_unix.c !pjlib 2.6 for POSIX initialized 11:29:35.021 sip_endpoint.c .Creating endpoint instance... 11:29:35.022 pjlib .select() I/O Queue created (0xf08730) 11:29:35.022 sip_endpoint.c .Module "mod-msg-print" registered 11:29:35.022 sip_transport. .Transport manager created. 11:29:35.022 pjsua_core.c .PJSUA state changed: NULL --> CREATED 11:29:35.022 sip_endpoint.c .Module "mod-pjsua-log" registered 11:29:35.022 sip_endpoint.c .Module "mod-tsx-layer" registered 11:29:35.022 sip_endpoint.c .Module "mod-stateful-util" registered 11:29:35.022 sip_endpoint.c .Module "mod-ua" registered 11:29:35.022 sip_endpoint.c .Module "mod-100rel" registered 11:29:35.022 sip_endpoint.c .Module "mod-pjsua" registered 11:29:35.022 sip_endpoint.c .Module "mod-invite" registered 11:29:35.024 alsa_dev.c ..ALSA driver found 0 devices 11:29:35.024 alsa_dev.c ..ALSA initialized 11:29:35.025 pjlib ..select() I/O Queue created (0xf1a448) 11:29:35.025 conference.c ..Creating conference bridge with 254 ports 11:29:35.025 Master/sound ..Using delay buffer with WSOLA. 11:29:35.030 sip_endpoint.c .Module "mod-evsub" registered 11:29:35.030 sip_endpoint.c .Module "mod-presence" registered 11:29:35.030 evsub.c .Event pkg "presence" registered by mod-presence 11:29:35.030 sip_endpoint.c .Module "mod-mwi" registered 11:29:35.030 evsub.c .Event pkg "message-summary" registered by mod-mwi 11:29:35.030 sip_endpoint.c .Module "mod-refer" registered 11:29:35.030 evsub.c .Event pkg "refer" registered by mod-refer 11:29:35.030 sip_endpoint.c .Module "mod-pjsua-pres" registered 11:29:35.030 sip_endpoint.c .Module "mod-pjsua-im" registered 11:29:35.030 sip_endpoint.c .Module "mod-pjsua-options" registered 11:29:35.030 pjsua_core.c .1 SIP worker threads created 11:29:35.030 pjsua_core.c .pjsua version 2.6 for Linux-4.4.0.89/x86_64/glibc-2.19 initialized 11:29:35.030 pjsua_core.c .PJSUA state changed: CREATED --> INIT 11:29:35.030 sip_endpoint.c Module "mod-default-handler" registered 11:29:35.030 pjsua_aud.c Creating file player: /root/pcm1644s.wav.. 11:29:35.030 wav_player.c .File player '/root/pcm1644s.wav' created: samp.rate=44100, ch=2, bufsize=4KB, filesize=1179KB 11:29:35.030 resample.c .resample created: high qualiy, large filter, in/out rate=44100/16000 11:29:35.030 resample.c .resample created: high qualiy, large filter, in/out rate=16000/44100 11:29:35.030 pjsua_aud.c .Player created, id=0, slot=1 11:29:35.031 pjsua_core.c SIP UDP socket reachable at 10.10.10.10:5060 11:29:35.031 udp0xf2d4d0 SIP UDP transport started, published address is 10.10.10.10:5060 11:29:35.031 pjsua_acc.c Adding account: id=<sip:10.10.10.10:5060> 11:29:35.031 pjsua_acc.c .Account <sip:10.10.10.10:5060> added with id 0 11:29:35.031 pjsua_acc.c Modifying account 0 11:29:35.031 pjsua_acc.c Acc 0: setting online status to 1.. 11:29:35.031 tcptp:5060 SIP TCP listener ready for incoming connections at 10.10.10.10:5060 11:29:35.031 pjsua_acc.c Adding account: id=<sip:10.10.10.10:5060;transport=TCP> 11:29:35.031 pjsua_acc.c .Account <sip:10.10.10.10:5060;transport=TCP> added with id 1 11:29:35.031 pjsua_acc.c Modifying account 1 11:29:35.031 pjsua_acc.c Acc 1: setting online status to 1.. 11:29:35.031 pjsua_acc.c Adding account: id=sip:user@123.123.123.123 11:29:35.032 pjsua_acc.c .Account sip:user@123.123.123.123 added with id 2 11:29:35.032 pjsua_acc.c .Acc 2: setting registration.. 11:29:35.032 endpoint ..Request msg REGISTER/cseq=49939 (tdta0xf3c790) created. 11:29:35.032 tsx0xf3e7f8 ...Transaction created for Request msg REGISTER/cseq=49940 (tdta0xf3c790) 11:29:35.032 tsx0xf3e7f8 ..Sending Request msg REGISTER/cseq=49940 (tdta0xf3c790) in state Null 11:29:35.032 sip_resolve.c ...Target '123.123.123.123:0' type=Unspecified resolved to '123.123.123.123:5060' type=UDP (UDP transport) 11:29:35.032 pjsua_core.c ...TX 575 bytes Request msg REGISTER/cseq=49940 (tdta0xf3c790) to UDP 123.123.123.123:5060: REGISTER sip:123.123.123.123 SIP/2.0 Via: SIP/2.0/UDP 10.10.10.10:5060;rport;branch=z9hG4bKPjuV0MzQPCbXezMg1LRHBtUprMF-iLRY90 Route: <sip:123.123.123.123;lr> Max-Forwards: 70 From: <sip:user@123.123.123.123>;tag=EZwmpP20B06a-l9KADuFFfMM7JfE5xK5 To: <sip:user@123.123.123.123> Call-ID: 5l6pPe4Sl1MScNZgbrYVWgMD29ufFh0n CSeq: 49940 REGISTER User-Agent: PJSUA v2.6 Linux-4.4.0.89/x86_64/glibc-2.19 Contact: <sip:user@10.10.10.10:5060;ob> Expires: 300 Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Content-Length: 0 --end msg-- 11:29:35.032 tsx0xf3e7f8 ...State changed from Null to Calling, event=TX_MSG 11:29:35.032 pjsua_acc.c ..Acc 2: Registration sent 11:29:35.032 pjsua_acc.c Acc 2: setting online status to 1.. 11:29:35.032 pjsua_pres.c Adding buddy: sip:21@123.123.123.123 11:29:35.032 pjsua_pres.c .Buddy 0 added. 11:29:35.032 pjsua_pres.c ..Buddy 0: updating presence.. 11:29:35.032 pjsua_aud.c Setting null sound device.. 11:29:35.032 pjsua_app.c .Turning sound device ON 11:29:35.032 pjsua_aud.c .Opening null sound device.. 11:29:35.033 pjsua_core.c PJSUA state changed: INIT --> STARTING 11:29:35.033 sip_endpoint.c .Module "mod-unsolicited-mwi" registered 11:29:35.033 pjsua_core.c .PJSUA state changed: STARTING --> RUNNING 11:29:35.033 main.c Ready: Success 11:29:35.033 pjsua_call.c Making call with acc #2 to sip:21@123.123.123.123 11:29:35.033 dlg0xf424b8 .UAC dialog created 11:29:35.033 dlg0xf424b8 ..Session count inc to 2 by mod-pjsua 11:29:35.033 pjsua_media.c .Call 0: initializing media.. 11:29:35.033 pjsua_media.c ..RTP socket reachable at 10.10.10.10:4000 11:29:35.033 pjsua_media.c ..RTCP socket reachable at 10.10.10.10:4001 11:29:35.033 pjsua_media.c ..Media index 0 selected for audio call 0 11:29:35.033 pjsua_media.c ..Call 0: media transport initialization complete: Success 11:29:35.033 dlg0xf424b8 ..Session count dec to 2 by mod-pjsua 11:29:35.033 dlg0xf424b8 .Module mod-invite added as dialog usage, data=0xf46cd8 11:29:35.033 dlg0xf424b8 ..Session count inc to 4 by mod-invite 11:29:35.033 dlg0xf424b8 .Module mod-100rel added as dialog usage, data=0xf4a400 11:29:35.033 dlg0xf424b8 .100rel module attached 11:29:35.033 inv0xf424b8 .UAC invite session created for dialog dlg0xf424b8 11:29:35.033 endpoint .Request msg INVITE/cseq=19787 (tdta0xf4a960) created. 11:29:35.033 inv0xf424b8 ..Sending Request msg INVITE/cseq=19787 (tdta0xf4a960) 11:29:35.034 dlg0xf424b8 ...Sending Request msg INVITE/cseq=19787 (tdta0xf4a960) 11:29:35.034 tsx0xf4d978 ....Transaction created for Request msg INVITE/cseq=19786 (tdta0xf4a960) 11:29:35.034 tsx0xf4d978 ...Sending Request msg INVITE/cseq=19786 (tdta0xf4a960) in state Null 11:29:35.034 sip_resolve.c ....Target '123.123.123.123:0' type=Unspecified resolved to '123.123.123.123:5060' type=UDP (UDP transport) 11:29:35.034 pjsua_core.c ....TX 1142 bytes Request msg INVITE/cseq=19786 (tdta0xf4a960) to UDP 123.123.123.123:5060: INVITE sip:21@123.123.123.123 SIP/2.0 Via: SIP/2.0/UDP 10.10.10.10:5060;rport;branch=z9hG4bKPjTB6l-4hftUhcljxWmzKerihPsRb.FHMO Max-Forwards: 70 From: sip:user@123.123.123.123;tag=5F-vcCg.74wrdot9MMXMcLa.FkdCFhy7 To: sip:21@123.123.123.123 Contact: <sip:user@10.10.10.10:5060;ob> Call-ID: LhMAxsYpxO2.f0dScRFaNmb.KRG.JkJM CSeq: 19786 INVITE Route: <sip:123.123.123.123;lr> Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Supported: replaces, 100rel, timer, norefersub Session-Expires: 1800 Min-SE: 90 User-Agent: PJSUA v2.6 Linux-4.4.0.89/x86_64/glibc-2.19 Content-Type: application/sdp Content-Length: 473 v=0 o=- 3711346175 3711346175 IN IP4 10.10.10.10 s=pjmedia b=AS:84 t=0 0 a=X-nat:0 m=audio 4000 RTP/AVP 98 97 99 104 3 0 8 9 96 c=IN IP4 10.10.10.10 b=TIAS:64000 a=rtcp:4001 IN IP4 10.10.10.10 a=sendrecv a=rtpmap:98 speex/16000 a=rtpmap:97 speex/8000 a=rtpmap:99 speex/32000 a=rtpmap:104 iLBC/8000 a=fmtp:104 mode=30 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:9 G722/8000 a=rtpmap:96 telephone-event/8000 a=fmtp:96 0-16 --end msg-- 11:29:35.034 tsx0xf4d978 ....State changed from Null to Calling, event=TX_MSG 11:29:35.034 dlg0xf424b8 .....Transaction tsx0xf4d978 state changed to Calling 11:29:35.034 pjsua_app.c .......Call 0 state changed to CALLING >>>> Account list: [ 0] <sip:10.10.10.10:5060>: does not register Online status: Online [ 1] <sip:10.10.10.10:5060;transport=TCP>: does not register Online status: Online *[ 2] sip:user@123.123.123.123: 100/In Progress (expires=0) Online status: Online Buddy list: [ 1] <?> sip:21@123.123.123.123 +=============================================================================+ | Call Commands: | Buddy, IM & Presence: | Account: | | | | | | m Make new call | +b Add new buddy .| +a Add new accnt | | M Make multiple calls | -b Delete buddy | -a Delete accnt. | | a Answer call | i Send IM | !a Modify accnt. | | h Hangup call (ha=all) | s Subscribe presence | rr (Re-)register | | H Hold call | u Unsubscribe presence | ru Unregister | | v re-inVite (release hold) | t ToGgle Online status | > Cycle next ac.| | U send UPDATE | T Set online status | < Cycle prev ac.| | ],[ Select next/prev call +--------------------------+-------------------+ | x Xfer call | Media Commands: | Status & Config: | | X Xfer with Replaces | | | | # Send RFC 2833 DTMF | cl List ports | d Dump status | | * Send DTMF with INFO | cc Connect port | dd Dump detailed | | dq Dump curr. call quality | cd Disconnect port | dc Dump config | | | V Adjust audio Volume | f Save config | | S Send arbitrary REQUEST | Cp Codec priorities | | +-----------------------------------------------------------------------------+ | q QUIT L ReLoad sleep MS echo [0|1|txt] n: detect NAT type | +=============================================================================+ You have 1 active call Current call id=0 to sip:21@123.123.123.123 [CALLING] >>> 11:29:35.041 sip_endpoint.c !Processing incoming message: Response msg 100/REGISTER/cseq=49940 (rdata0xf375f8) 11:29:35.041 pjsua_core.c .RX 434 bytes Response msg 100/REGISTER/cseq=49940 (rdata0xf375f8) from UDP 123.123.123.123:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.10.10.10:5060;rport=5060;branch=z9hG4bKPjuV0MzQPCbXezMg1LRHBtUprMF-iLRY90 To: <sip:user@123.123.123.123> From: <sip:user@123.123.123.123>;tag=EZwmpP20B06a-l9KADuFFfMM7JfE5xK5 Call-ID: 5l6pPe4Sl1MScNZgbrYVWgMD29ufFh0n CSeq: 49940 REGISTER Allow: REGISTER, INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, INFO, SUBSCRIBE, UPDATE User-Agent: Swyx IpPbxSrv/10.40.0.304 Content-Length: 0 --end msg-- 11:29:35.041 tsx0xf3e7f8 .Incoming Response msg 100/REGISTER/cseq=49940 (rdata0xf375f8) in state Calling 11:29:35.041 tsx0xf3e7f8 ..State changed from Calling to Proceeding, event=RX_MSG 11:29:35.041 sip_endpoint.c Processing incoming message: Response msg 404/INVITE/cseq=19786 (rdata0x7fd2540008e8) 11:29:35.041 pjsua_core.c .RX 444 bytes Response msg 404/INVITE/cseq=19786 (rdata0x7fd2540008e8) from UDP 123.123.123.123:5060: SIP/2.0 404 Not Found Via: SIP/2.0/UDP 10.10.10.10:5060;rport=5060;branch=z9hG4bKPjTB6l-4hftUhcljxWmzKerihPsRb.FHMO To: <sip:21@123.123.123.123>;tag=95645c56 From: <sip:user@123.123.123.123>;tag=5F-vcCg.74wrdot9MMXMcLa.FkdCFhy7 Call-ID: LhMAxsYpxO2.f0dScRFaNmb.KRG.JkJM CSeq: 19786 INVITE Allow: REGISTER, INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, INFO, SUBSCRIBE, UPDATE User-Agent: Swyx IpPbxSrv/10.40.0.304 Content-Length: 0 --end msg-- 11:29:35.041 tsx0xf4d978 .Incoming Response msg 404/INVITE/cseq=19786 (rdata0x7fd2540008e8) in state Calling 11:29:35.041 endpoint ..Request msg ACK/cseq=19786 (tdta0x7fd254002810) created. 11:29:35.041 pjsua_core.c ..TX 360 bytes Request msg ACK/cseq=19786 (tdta0x7fd254002810) to UDP 123.123.123.123:5060: ACK sip:21@123.123.123.123 SIP/2.0 Via: SIP/2.0/UDP 10.10.10.10:5060;rport;branch=z9hG4bKPjTB6l-4hftUhcljxWmzKerihPsRb.FHMO Max-Forwards: 70 From: sip:user@123.123.123.123;tag=5F-vcCg.74wrdot9MMXMcLa.FkdCFhy7 To: sip:21@123.123.123.123;tag=95645c56 Call-ID: LhMAxsYpxO2.f0dScRFaNmb.KRG.JkJM CSeq: 19786 ACK Route: <sip:123.123.123.123;lr> Content-Length: 0 --end msg-- 11:29:35.041 tsx0xf4d978 ..State changed from Calling to Completed, event=RX_MSG 11:29:35.041 dlg0xf424b8 ...Received Response msg 404/INVITE/cseq=19786 (rdata0x7fd2540008e8) 11:29:35.041 dlg0xf424b8 ...Transaction tsx0xf4d978 state changed to Completed 11:29:35.041 pjsua_app.c .....Call 0 is DISCONNECTED [reason=404 (Not Found)] 11:29:35.041 pjsua_app.c .....Call 0 disconnected, dumping media stats.. 11:29:35.041 pjsua_app_comm ..... [DISCONNCTD] To: sip:21@123.123.123.123 Call time: 00h:00m:00s, 1st res in 8 ms, conn in 0ms 11:29:35.041 pjsua_media.c .....Call 0: deinitializing media.. 11:29:35.041 pjsua_media.c ......Call 0: cleaning up provisional media, prov_med_cnt=1, med_cnt=0 11:29:35.041 dlg0xf424b8 .....Session count dec to 1 by mod-invite 11:29:35.041 tdta0xf4a960 ..Destroying txdata Request msg INVITE/cseq=19786 (tdta0xf4a960) 11:29:35.041 sip_endpoint.c Processing incoming message: Response msg 200/REGISTER/cseq=49940 (rdata0x7fd2540008e8) 11:29:35.041 pjsua_core.c .RX 536 bytes Response msg 200/REGISTER/cseq=49940 (rdata0x7fd2540008e8) from UDP 123.123.123.123:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.10.10.10:5060;rport=5060;branch=z9hG4bKPjuV0MzQPCbXezMg1LRHBtUprMF-iLRY90 Contact: <sip:user@10.10.10.10:5060;ob>;expires=120 To: <sip:user@123.123.123.123>;tag=20273559 From: <sip:user@123.123.123.123>;tag=EZwmpP20B06a-l9KADuFFfMM7JfE5xK5 Call-ID: 5l6pPe4Sl1MScNZgbrYVWgMD29ufFh0n CSeq: 49940 REGISTER Allow: REGISTER, INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, INFO, SUBSCRIBE, UPDATE Date: Thu, 10 Aug 2017 09:29:35 GMT User-Agent: Swyx IpPbxSrv/10.40.0.304 Content-Length: 0 --end msg-- 11:29:35.041 tsx0xf3e7f8 .Incoming Response msg 200/REGISTER/cseq=49940 (rdata0x7fd2540008e8) in state Proceeding 11:29:35.041 tsx0xf3e7f8 ..State changed from Proceeding to Completed, event=RX_MSG 11:29:35.041 pjsua_acc.c ....SIP outbound status for acc 2 is not active 11:29:35.041 pjsua_acc.c ....sip:user@123.123.123.123: registration success, status=200 (OK), will re-register in 120 seconds 11:29:35.041 pjsua_acc.c ....Keep-alive timer started for acc 2, destination:123.123.123.123:5060, interval:15s 11:29:36.032 pjsua_aud.c Closing sound device after idle for 1 second(s) 11:29:36.032 pjsua_app.c .Turning sound device OFF 11:29:36.032 pjsua_aud.c .Closing null sound device.. Cannot switch back to console from file redirection 11:29:39.085 pjsua_core.c !Shutting down, flags=0... 11:29:39.085 pjsua_core.c PJSUA state changed: RUNNING --> CLOSING 11:29:39.095 pjsua_call.c .Hangup all calls.. 11:29:39.095 pjsua_media.c .Call 0: deinitializing media.. 11:29:39.095 pjsua_pres.c .Shutting down presence.. 11:29:39.095 pjsua_acc.c .Acc 2: setting unregistration.. 11:29:39.095 endpoint ..Request msg REGISTER/cseq=49940 (tdta0xf410c0) created. 11:29:39.095 tsx0xf471d8 ...Transaction created for Request msg REGISTER/cseq=49941 (tdta0xf410c0) 11:29:39.096 tsx0xf471d8 ..Sending Request msg REGISTER/cseq=49941 (tdta0xf410c0) in state Null 11:29:39.096 sip_resolve.c ...Target '123.123.123.123:0' type=Unspecified resolved to '123.123.123.123:5060' type=UDP (UDP transport) 11:29:39.096 pjsua_core.c ...TX 475 bytes Request msg REGISTER/cseq=49941 (tdta0xf410c0) to UDP 123.123.123.123:5060: REGISTER sip:123.123.123.123 SIP/2.0 Via: SIP/2.0/UDP 10.10.10.10:5060;rport;branch=z9hG4bKPjd.u8djoJM9ASUYeIzW-6DWhs8fw3TNe. Route: <sip:123.123.123.123;lr> Max-Forwards: 70 From: <sip:user@123.123.123.123>;tag=VJiLrz.hUB3V3AtQDKbGeyivlPBc3rEW To: <sip:user@123.123.123.123> Call-ID: 5l6pPe4Sl1MScNZgbrYVWgMD29ufFh0n CSeq: 49941 REGISTER User-Agent: PJSUA v2.6 Linux-4.4.0.89/x86_64/glibc-2.19 Contact: <sip:user@10.10.10.10:5060;ob> Expires: 0 Content-Length: 0 --end msg-- 11:29:39.098 tsx0xf471d8 ...State changed from Null to Calling, event=TX_MSG 11:29:39.099 pjsua_acc.c ..Acc 2: Unregistration sent 11:29:39.100 sip_endpoint.c .Processing incoming message: Response msg 200/REGISTER/cseq=49941 (rdata0x7fd2540008e8) 11:29:39.101 pjsua_core.c ..RX 534 bytes Response msg 200/REGISTER/cseq=49941 (rdata0x7fd2540008e8) from UDP 123.123.123.123:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.10.10.10:5060;rport=5060;branch=z9hG4bKPjd.u8djoJM9ASUYeIzW-6DWhs8fw3TNe. Contact: <sip:user@10.10.10.10:5060;ob>;expires=0 To: <sip:user@123.123.123.123>;tag=344af210 From: <sip:user@123.123.123.123>;tag=VJiLrz.hUB3V3AtQDKbGeyivlPBc3rEW Call-ID: 5l6pPe4Sl1MScNZgbrYVWgMD29ufFh0n CSeq: 49941 REGISTER Allow: REGISTER, INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, INFO, SUBSCRIBE, UPDATE Date: Thu, 10 Aug 2017 09:29:39 GMT User-Agent: Swyx IpPbxSrv/10.40.0.304 Content-Length: 0 --end msg-- 11:29:39.103 tsx0xf471d8 ..Incoming Response msg 200/REGISTER/cseq=49941 (rdata0x7fd2540008e8) in state Calling 11:29:39.103 tsx0xf471d8 ...State changed from Calling to Completed, event=RX_MSG 11:29:39.103 pjsua_acc.c .....sip:user@123.123.123.123: unregistration success 11:29:40.041 tsx0xf3e7f8 .Timeout timer event 11:29:40.042 tsx0xf3e7f8 ..State changed from Completed to Terminated, event=TIMER 11:29:40.042 tsx0xf3e7f8 .Timeout timer event 11:29:40.042 tsx0xf3e7f8 ..State changed from Terminated to Destroyed, event=TIMER 11:29:40.042 tdta0xf3c790 ...Destroying txdata Request msg REGISTER/cseq=49940 (tdta0xf3c790) 11:29:40.043 tsx0xf3e7f8 .Transaction destroyed! 11:29:40.103 pjsua_core.c .Destroying... 11:29:40.104 pjsua_media.c .Shutting down media.. 11:29:40.526 sip_endpoint.c .Destroying endpoing instance.. 11:29:40.526 sip_transactio .Stopping transaction layer module 11:29:40.526 tsx0xf4d978 .Request to terminate transaction 11:29:40.527 tsx0xf4d978 ..State changed from Completed to Terminated, event=USER 11:29:40.527 dlg0xf424b8 ...Transaction tsx0xf4d978 state changed to Terminated 11:29:40.527 dlg0xf424b8 ....Dialog destroyed 11:29:40.527 tdta0x7fd25400 .Destroying txdata Request msg ACK/cseq=19786 (tdta0x7fd254002810) 11:29:40.527 tsx0xf4d978 .Transaction destroyed! 11:29:40.527 tsx0xf471d8 .Request to terminate transaction 11:29:40.527 tsx0xf471d8 ..State changed from Completed to Terminated, event=USER 11:29:40.528 tdta0xf410c0 .Destroying txdata Request msg REGISTER/cseq=49941 (tdta0xf410c0) 11:29:40.528 tsx0xf471d8 .Transaction destroyed! 11:29:40.528 sip_transactio .Stopped transaction layer module 11:29:40.528 sip_endpoint.c .Module "mod-default-handler" unregistered 11:29:40.528 sip_endpoint.c .Module "mod-unsolicited-mwi" unregistered 11:29:40.528 sip_endpoint.c .Module "mod-pjsua-options" unregistered 11:29:40.528 sip_endpoint.c .Module "mod-pjsua-im" unregistered 11:29:40.528 sip_endpoint.c .Module "mod-pjsua-pres" unregistered 11:29:40.529 sip_endpoint.c .Module "mod-pjsua" unregistered 11:29:40.529 sip_endpoint.c .Module "mod-stateful-util" unregistered 11:29:40.529 sip_endpoint.c .Module "mod-refer" unregistered 11:29:40.529 sip_endpoint.c .Module "mod-mwi" unregistered 11:29:40.529 sip_endpoint.c .Module "mod-presence" unregistered 11:29:40.529 sip_endpoint.c .Module "mod-evsub" unregistered 11:29:40.529 sip_endpoint.c .Module "mod-invite" unregistered 11:29:40.529 sip_endpoint.c .Module "mod-100rel" unregistered 11:29:40.529 sip_endpoint.c .Module "mod-ua" unregistered 11:29:40.530 sip_transactio .Transaction layer module destroyed 11:29:40.530 sip_endpoint.c .Module "mod-tsx-layer" unregistered 11:29:40.530 sip_endpoint.c .Module "mod-msg-print" unregistered 11:29:40.530 sip_endpoint.c .Module "mod-pjsua-log" unregistered 11:29:40.530 sip_transport. .Destroying transport manager 11:29:40.531 udp0xf2d4d0 .SIP UDP transport destroyed 11:29:40.531 tcptp:5060 .SIP TCP transport destroyed 11:29:40.532 sip_endpoint.c .Endpoint 0xefd998 destroyed 11:29:40.532 pcm1644s.wav .Pool is not released by application, releasing now 11:29:40.532 pjsua_core.c .PJSUA state changed: CLOSING --> NULL 11:29:40.532 pjsua_core.c .PJSUA destroyed... Dies ist die PJSIP Konfiguration sowie der cli Aufruf: Quote --id sip:zabbix@123.123.123.123 --registrar sip:123.123.123.123 --realm * --username user --password password --null-audio --bound-addr=111.111.111.111 --outbound=sip:123.123.123.123 $ ./pjsua-x86_64-unknown-linux-gnu --config-file /etc/pjsip/swyx01.conf --play-file /root/pcm1644s.wav --auto-play --duration 60 --max-calls 1 sip:21@123.123.123.123 --app-log-level=6 --log-level=6 --log-file=test Der Swyx Server ist nicht unter Last, wurde auch nochmal updated jetzt auf die aktuelle Version, arbeitet mit ~80 Nebenstellen inkl. ~17 SIP Geräten einwandfrei seit Jahren. Das Swyx tracinglog ist gar nicht hilfreich da es quasi nichts anzeigt bei den fehlerhaften Versuchen. Hat jemand eine Idee was da schief laufen könnte? 404 Errors ergeben für mich keinen Sinn wenn es nur sporadisch auftritt. Ich kann es auch nicht genau reproduzieren, auch nicht von irgendwelchen Zeitabständen zwischen den Versuchen oder ähnliches. Need help. Danke schonmal! Link to comment Share on other sites More sharing options...
Most Valued User Virikas Posted August 21, 2017 Most Valued User #2 Share Posted August 21, 2017 Aufgrund der ganzen anonymisierungen die du Vorgenommen hast, ist es etwas schwer das zu lesen. Dein PJSIP Client ist 10.10.10.10 mit User Zabbix? Wer ist die 21 die gerufen wird? Ein Callrouting User? Da das 404 vom Swyxserver (123.123.123.123) gesendet wird, solltest du es aber zumindest das im IPPbxSrv Trace finden. Link to comment Share on other sites More sharing options...
MichaB Posted October 19, 2017 #3 Share Posted October 19, 2017 Die Registrierung des pjsip clients scheitert, weil die Antwort des Server vermutlich den Client nicht schnell genug findet. Route: <sip:123.123.123.123;lr> ??? Dieser sendet dann aktiv die Abmeldung im Register, Expires: 0 !!! Der SwyxServer tut sich zusätzlich mit ALG's, die Quell-IP's ändern, ebenfalls recht schwer, deshalb könnte der Blick in's Trace des Server evtl. weiter helfen. Aber die erste Ansatz ist Richtung Routing REGISTER sip:123.123.123.123 SIP/2.0 Via: SIP/2.0/UDP 10.10.10.10:5060;rport;branch=z9hG4bKPjd.u8djoJM9ASUYeIzW-6DWhs8fw3TNe. Route: <sip:123.123.123.123;lr> Max-Forwards: 70 From: <sip:user@123.123.123.123>;tag=VJiLrz.hUB3V3AtQDKbGeyivlPBc3rEW To: <sip:user@123.123.123.123> Call-ID: 5l6pPe4Sl1MScNZgbrYVWgMD29ufFh0n CSeq: 49941 REGISTER User-Agent: PJSUA v2.6 Linux-4.4.0.89/x86_64/glibc-2.19 Contact: <sip:user@10.10.10.10:5060;ob> Expires: 0 Link to comment Share on other sites More sharing options...
Recommended Posts
Archived
This topic is now archived and is closed to further replies.