Hi All, I'm trying to integrate Rtpengine into our MS Lync testing estate (so ther

No RTP/SRTP Sent,about sipwise/rtpengine

Comments (50)

rfuchs commented on June 24, 2024

Could you please post the full rtpengine log output for a test call you've made, thanks.

from rtpengine.

edjames99 commented on June 24, 2024

Is there an rtpengine specific log as separate from the kamailio log ?

from rtpengine.

rfuchs commented on June 24, 2024

Yes, the rtpengine daemon logs separately. It logs to syslog using the "daemon" facility.

from rtpengine.

edjames99 commented on June 24, 2024

Please find the log file output for a test call. I tried to get LOG_DEBUG to output (tried defining env variable $DBG, changing the make file to always include -D__DEBUG=1 , removing the __DEBUG section from iLog & running rtpengine with a --log-level=7) but I couldn't get any LOG_DEBUG output. If you search backwards from the bottom for OUT_DIALOG_FROM_LYNCIT then that's the first call coming in from the SRTP side. Thanks very much for your help it's much appreciated.
Ed James

Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[4928]: NOTICE: <core> [main.c:730]: handle_sigs(): Thank you for flying kamailio!!!
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[4938]: INFO: <core> [main.c:841]: sig_usr(): INFO: signal 15 received
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[4937]: INFO: <core> [main.c:841]: sig_usr(): INFO: signal 15 received
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[4936]: INFO: <core> [main.c:841]: sig_usr(): INFO: signal 15 received
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[4935]: INFO: <core> [main.c:841]: sig_usr(): INFO: signal 15 received
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[4934]: INFO: <core> [main.c:841]: sig_usr(): INFO: signal 15 received
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[4933]: INFO: <core> [main.c:841]: sig_usr(): INFO: signal 15 received
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[4932]: INFO: <core> [main.c:841]: sig_usr(): INFO: signal 15 received
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[4928]: ERROR: ctl [ctl.c:379]: mod_destroy(): ERROR: ctl: could not delete unix socket /tmp/kamailio_ctl: Operation not permitted (1)
Jul 24 15:18:03 localhost kamailio: INFO: tls [tls_init.c:385]: init_tls_compression(): tls: init_tls: disabling compression...
Jul 24 15:18:03 localhost kamailio: INFO: <core> [tcp_main.c:4836]: init_tcp(): init_tcp: using epoll_lt as the io watch method (auto detected)
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5028]: INFO: rr [../outbound/api.h:54]: ob_load_api(): Failed to import bind_ob
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5028]: INFO: rr [rr_mod.c:159]: mod_init(): outbound module not available
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5028]: INFO: path [../outbound/api.h:54]: ob_load_api(): Failed to import bind_ob
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5028]: INFO: path [path_mod.c:147]: mod_init(): outbound module not available
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5028]: INFO: tls [tls_init.c:549]: init_tls_h(): tls: _init_tls_h:  compiled  with  openssl  version "OpenSSL 1.0.1e-fips 11 Feb 2013" (0x1000105f), kerberos support: on, compression: on
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5028]: INFO: tls [tls_init.c:557]: init_tls_h(): tls: init_tls_h: installed openssl library version "OpenSSL 1.0.1e-fips 11 Feb 2013" (0x1000105f), kerberos support: on,  zlib compression: on#012 compiler: gcc -fPIC -DOPENSSL_PIC -DZLIB -DOPENSSL_THREADS -D_REENTRANT -DDSO_DLFCN -DHAVE_DLFCN_H -DKRB5_MIT -m64 -DL_ENDIAN -DTERMIO -Wall -O2 -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector --param=ssp-buffer-size=4 -m64 -mtune=generic -Wa,--noexecstack -DPURIFY -DOPENSSL_IA32_SSE2 -DOPENSSL_BN_ASM_MONT -DOPENSSL_BN_ASM_MONT5 -DOPENSSL_BN_ASM_GF2m -DSHA1_ASM -DSHA256_ASM -DSHA512_ASM -DMD5_ASM -DAES_ASM -DVPAES_ASM -DBSAES_ASM -DWHIRLPOOL_ASM -DGHASH_ASM
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5028]: WARNING: tls [tls_init.c:611]: init_tls_h(): tls: openssl bug #1491 (crash/mem leaks on low memory) workaround enabled (on low memory tls operations will fail preemptively) with free memory thresholds 4194304 and 2097152 bytes
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5028]: INFO: <core> [cfg/cfg_ctx.c:613]: cfg_set_now(): INFO: cfg_set_now(): tls.low_mem_threshold1 has been changed to 4194304
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5028]: INFO: <core> [cfg/cfg_ctx.c:613]: cfg_set_now(): INFO: cfg_set_now(): tls.low_mem_threshold2 has been changed to 2097152
Jul 24 15:18:03 localhost rtpengine[4945]: Got valid command from 127.0.0.1:43833: ping - { "command": "ping" }
Jul 24 15:18:03 localhost rtpengine[4945]: Returning to SIP proxy: d6:result4:ponge
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5028]: INFO: rtpproxy-ng [rtpproxy.c:1430]: rtpp_test(): rtp proxy udp:127.0.0.1:2223 found, support for it enabled
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5028]: INFO: tls [tls_domain.c:190]: fill_missing(): TLSs<default>: tls_method=9
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5028]: INFO: tls [tls_domain.c:202]: fill_missing(): TLSs<default>: certificate='/usr/local/etc/kamailio/Kam_CertOnly.pem'
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5028]: INFO: tls [tls_domain.c:209]: fill_missing(): TLSs<default>: ca_list='(null)'
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5028]: INFO: tls [tls_domain.c:216]: fill_missing(): TLSs<default>: crl='(null)'
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5028]: INFO: tls [tls_domain.c:220]: fill_missing(): TLSs<default>: require_certificate=0
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5028]: INFO: tls [tls_domain.c:227]: fill_missing(): TLSs<default>: cipher_list='(null)'
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5028]: INFO: tls [tls_domain.c:234]: fill_missing(): TLSs<default>: private_key='/usr/local/etc/kamailio/Kam_KeyOnly.pem'
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5028]: INFO: tls [tls_domain.c:238]: fill_missing(): TLSs<default>: verify_certificate=0
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5028]: INFO: tls [tls_domain.c:241]: fill_missing(): TLSs<default>: verify_depth=9
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5028]: INFO: tls [tls_domain.c:579]: set_verification(): TLSs<default>: No client certificate required and no checks performed
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5028]: INFO: tls [tls_domain.c:190]: fill_missing(): TLSc<default>: tls_method=9
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5028]: INFO: tls [tls_domain.c:202]: fill_missing(): TLSc<default>: certificate='(null)'
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5028]: INFO: tls [tls_domain.c:209]: fill_missing(): TLSc<default>: ca_list='/usr/local/etc/kamailio/RS001738_CA.pem'
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5028]: INFO: tls [tls_domain.c:216]: fill_missing(): TLSc<default>: crl='(null)'
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5028]: INFO: tls [tls_domain.c:220]: fill_missing(): TLSc<default>: require_certificate=1
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5028]: INFO: tls [tls_domain.c:227]: fill_missing(): TLSc<default>: cipher_list='(null)'
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5028]: INFO: tls [tls_domain.c:234]: fill_missing(): TLSc<default>: private_key='(null)'
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5028]: INFO: tls [tls_domain.c:238]: fill_missing(): TLSc<default>: verify_certificate=1
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5028]: INFO: tls [tls_domain.c:241]: fill_missing(): TLSc<default>: verify_depth=9
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5028]: INFO: tls [tls_domain.c:564]: set_verification(): TLSc<default>: Server MUST present valid certificate
Jul 24 15:18:03 localhost rtpengine[4945]: Got valid command from 127.0.0.1:32775: ping - { "command": "ping" }
Jul 24 15:18:03 localhost rtpengine[4945]: Returning to SIP proxy: d6:result4:ponge
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5028]: INFO: rtpproxy-ng [rtpproxy.c:1430]: rtpp_test(): rtp proxy udp:127.0.0.1:2223 found, support for it enabled
Jul 24 15:18:03 localhost rtpengine[4945]: Got valid command from 127.0.0.1:42773: ping - { "command": "ping" }
Jul 24 15:18:03 localhost rtpengine[4945]: Returning to SIP proxy: d6:result4:ponge
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5033]: INFO: rtpproxy-ng [rtpproxy.c:1430]: rtpp_test(): rtp proxy udp:127.0.0.1:2223 found, support for it enabled
Jul 24 15:18:03 localhost rtpengine[4945]: Got valid command from 127.0.0.1:51022: ping - { "command": "ping" }
Jul 24 15:18:03 localhost rtpengine[4945]: Returning to SIP proxy: d6:result4:ponge
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5032]: INFO: rtpproxy-ng [rtpproxy.c:1430]: rtpp_test(): rtp proxy udp:127.0.0.1:2223 found, support for it enabled
Jul 24 15:18:03 localhost rtpengine[4945]: Got valid command from 127.0.0.1:42187: ping - { "command": "ping" }
Jul 24 15:18:03 localhost rtpengine[4945]: Returning to SIP proxy: d6:result4:ponge
Jul 24 15:18:03 localhost rtpengine[4945]: Got valid command from 127.0.0.1:47390: ping - { "command": "ping" }
Jul 24 15:18:03 localhost rtpengine[4945]: Returning to SIP proxy: d6:result4:ponge
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5035]: INFO: rtpproxy-ng [rtpproxy.c:1430]: rtpp_test(): rtp proxy udp:127.0.0.1:2223 found, support for it enabled
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5035]: INFO: ctl [io_listener.c:225]: io_listen_loop(): io_listen_loop:  using epoll_lt io watch method (config)
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5036]: INFO: rtpproxy-ng [rtpproxy.c:1430]: rtpp_test(): rtp proxy udp:127.0.0.1:2223 found, support for it enabled
Jul 24 15:18:03 localhost rtpengine[4945]: Got valid command from 127.0.0.1:47165: ping - { "command": "ping" }
Jul 24 15:18:03 localhost rtpengine[4945]: Returning to SIP proxy: d6:result4:ponge
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5039]: INFO: rtpproxy-ng [rtpproxy.c:1430]: rtpp_test(): rtp proxy udp:127.0.0.1:2223 found, support for it enabled
Jul 24 15:18:03 localhost rtpengine[4945]: Got valid command from 127.0.0.1:43882: ping - { "command": "ping" }
Jul 24 15:18:03 localhost rtpengine[4945]: Returning to SIP proxy: d6:result4:ponge
Jul 24 15:18:03 localhost /usr/local/sbin/kamailio[5040]: INFO: rtpproxy-ng [rtpproxy.c:1430]: rtpp_test(): rtp proxy udp:127.0.0.1:2223 found, support for it enabled
Jul 24 15:18:07 localhost /usr/local/sbin/kamailio[5036]: NOTICE: <script>: Enter main request route
Jul 24 15:18:07 localhost /usr/local/sbin/kamailio[5036]: INFO: <script>: Main request route OPTIONS
Jul 24 15:18:07 localhost /usr/local/sbin/kamailio[5039]: NOTICE: <script>: Enter main request route
Jul 24 15:18:07 localhost /usr/local/sbin/kamailio[5039]: INFO: <script>: Main request route OPTIONS
Jul 24 15:18:09 localhost /usr/local/sbin/kamailio[5036]: NOTICE: <script>: Enter main request route
Jul 24 15:18:09 localhost /usr/local/sbin/kamailio[5036]: INFO: <script>: Main request route INVITE
Jul 24 15:18:09 localhost /usr/local/sbin/kamailio[5036]: INFO: <script>: OUT_DIALOG_FROM_LYNCIT
Jul 24 15:18:09 localhost rtpengine[4945]: Got valid command from 127.0.0.1:42187: offer - { "sdp": "v=0#015#012o=- 0 0 IN IP4 192.168.2.106#015#012s=session#015#012c=IN IP4 192.168.2.106#015#012b=CT:100000#015#012t=0 0#015#012m=audio 33042 RTP/SAVP 0 8 97 101 13#015#012c=IN IP4 192.168.2.106#015#012a=rtcp:33043#015#012a=sendrecv#015#012a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:yTsMgQAYfsg5Eq8u9LJLKOcIafzyzK19UwssmASF|2^31|1:1#015#012a=crypto:2 AES_CM_128_HMAC_SHA1_80 inline:A1Jzi0OLDgUB6l8uXfp7vAyNTzb4w8CcwjRrPS7G|2^31#015#012a=rtpmap:0 PCMU/8000#015#012a=rtpmap:8 PCMA/8000#015#012a=label:main-audio#015#012a=rtcp-rsize#015#012a=x-ssrc-range:89-89#015#012a=x-source:main-audio#015#012a=rtcp-fb:\* x-message app recv:dsh#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=rtpmap:13 CN/8000#015#012", "ICE": "remove", "flags": [ "force", "trust-address" ], "replace": [ "origin", "session-connection" ], "transport-protocol": "RTP/AVP", "call-id": "2cb67bfe-5a85-4010-8e20-572bd9cd24f6", "received-from": [ "IP4", "192.168.2.106" ], "from-tag": "a5bc7e554", "command": "offer" }
Jul 24 15:18:09 localhost rtpengine[4945]: ERJ LOG_ERROR parse crypto 1 31
Jul 24 15:18:09 localhost rtpengine[4945]: ERJ LOG_INFO parse crypto 1 31
Jul 24 15:18:09 localhost rtpengine[4945]: ERJ parse crypto 2 2147483648
Jul 24 15:18:09 localhost rtpengine[4945]: ERJ LOG_ERROR parse crypto 1 31
Jul 24 15:18:09 localhost rtpengine[4945]: ERJ LOG_INFO parse crypto 1 31
Jul 24 15:18:09 localhost rtpengine[4945]: ERJ parse crypto 2 2147483648
Jul 24 15:18:09 localhost rtpengine[4945]: [2cb67bfe-5a85-4010-8e20-572bd9cd24f6] Creating new call
Jul 24 15:18:09 localhost rtpengine[4945]: [2cb67bfe-5a85-4010-8e20-572bd9cd24f6] Returning to SIP proxy: d3:sdp422:v=0#015#012o=- 0 0 IN IP4 10.1.0.127#015#012s=session#015#012c=IN IP4 10.1.0.127#015#012b=CT:100000#015#012t=0 0#015#012m=audio 30000 RTP/AVP 0 8 97 101 13#015#012c=IN IP4 10.1.0.127#015#012a=rtpmap:0 PCMU/8000#015#012a=rtpmap:8 PCMA/8000#015#012a=label:main-audio#015#012a=rtcp-rsize#015#012a=x-ssrc-range:89-89#015#012a=x-source:main-audio#015#012a=rtcp-fb:\* x-message app recv:dsh#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=rtpmap:13 CN/8000#015#012a=sendrecv#015#012a=rtcp:30001#015#0126:result2:oke
Jul 24 15:18:54 localhost /usr/local/sbin/kamailio[5036]: NOTICE: <script>: Enter main request route
Jul 24 15:18:54 localhost /usr/local/sbin/kamailio[5036]: INFO: <script>: Main request route INVITE
Jul 24 15:18:54 localhost /usr/local/sbin/kamailio[5036]: INFO: <script>: OUT_DIALOG_TO_LYNCIT
Jul 24 15:18:54 localhost /usr/local/sbin/kamailio[5036]: INFO: <script>: sending to 192.168.2.106:5076 ERJ01
Jul 24 15:18:54 localhost /usr/local/sbin/kamailio[5036]: INFO: <script>: ERJ05 - out dialog to lyncit
Jul 24 15:18:54 localhost /usr/local/sbin/kamailio[5036]: INFO: <script>: ERJ06 - out dialog to lyncit INVITE
Jul 24 15:18:54 localhost /usr/local/sbin/kamailio[5036]: INFO: <script>: ERJ07 - out dialog to lyncit INVITE sdp
Jul 24 15:18:54 localhost rtpengine[4945]: Got valid command from 127.0.0.1:42187: offer - { "sdp": "v=0#015#012o=Redwood_INX 515320 515320 IN IP4 10.1.0.121#015#012s=Redwood Media Server#015#012c=IN IP4 10.1.0.121#015#012t=0 0#015#012m=audio 19130 RTP/AVP 8 97 96 13#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:96 telephone-event/8000#015#012a=fmtp:96 0-16#015#012a=rtpmap:13 CN/8000#015#012a=ptime:20#015#012a=sendrecv#015#012a=rtcp:19131#015#012a=label:main-audio#015#012", "ICE": "force", "flags": [ "force", "trust-address" ], "replace": [ "origin", "session-connection" ], "transport-protocol": "RTP/SAVP", "call-id": "YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.", "received-from": [ "IP4", "10.1.0.119" ], "from-tag": "422ab553", "command": "offer" }
Jul 24 15:18:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] Creating new call
Jul 24 15:18:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] Returning to SIP proxy: d3:sdp714:v=0#015#012o=Redwood_INX 515320 515320 IN IP4 10.1.0.127#015#012s=Redwood Media Server#015#012c=IN IP4 10.1.0.127#015#012t=0 0#015#012a=ice-lite#015#012m=audio 30004 RTP/SAVP 8 97 96 13#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:96 telephone-event/8000#015#012a=fmtp:96 0-16#015#012a=rtpmap:13 CN/8000#015#012a=ptime:20#015#012a=label:main-audio#015#012a=sendrecv#015#012a=rtcp:30005#015#012a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:45ddxkGAgIgJY7MlhjUQUDYLpiWyWuG/GN7FY6rr#015#012a=setup:actpass#015#012a=fingerprint:sha-1 6C:C3:2F:5F:72:6E:EE:76:15:7E:72:87:29:38:80:4F:BD:03:71:62#015#012a=ice-ufrag:0xOvNbVt#015#012a=ice-pwd:7SyAP39k1JtcwdUzJWwe7oB7TpDG#015#012a=candidate:GJzGDWWqDztv0n8z 1 UDP 2130706432 10.1.0.127 30004 typ host#015#012a=candidate:GJzGDWWqDztv0n8z 2 UDP 2130706431 10.1.0.127 30005 typ host#015#0126:result2:oke
Jul 24 15:18:54 localhost /usr/local/sbin/kamailio[5039]: INFO: <script>: ERJ21 - 183 reply to INVITE to LYNCIT
Jul 24 15:18:54 localhost rtpengine[4945]: Got valid command from 127.0.0.1:47165: answer - { "sdp": "v=0#015#012o=- 0 0 IN IP4 192.168.2.106#015#012s=session#015#012c=IN IP4 192.168.2.106#015#012b=CT:100000#015#012t=0 0#015#012m=audio 33488 RTP/SAVP 8 97 96 13#015#012c=IN IP4 192.168.2.106#015#012a=rtcp:33489#015#012a=sendrecv#015#012a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:mMRsrZmELQh9fqusFxkwdue5wSmrLnMCRLngxH0A|2^31|1:1#015#012a=rtpmap:8 PCMA/8000#015#012a=ptime:20#015#012a=label:main-audio#015#012a=x-ssrc-range:91-91#015#012a=x-source:main-audio#015#012a=rtcp-fb:\* x-message app recv:dsh#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:96 telephone-event/8000#015#012a=fmtp:96 0-16#015#012a=rtpmap:13 CN/8000#015#012", "ICE": "remove", "transport-protocol": "RTP/AVP", "call-id": "YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.", "received-from": [ "IP4", "192.168.2.106" ], "from-tag": "422ab553", "to-tag": "ad508ba5ae", "command": "answer" }
Jul 24 15:18:54 localhost rtpengine[4945]: ERJ LOG_ERROR parse crypto 1 31
Jul 24 15:18:54 localhost rtpengine[4945]: ERJ LOG_INFO parse crypto 1 31
Jul 24 15:18:54 localhost rtpengine[4945]: ERJ parse crypto 2 2147483648
Jul 24 15:18:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] Returning to SIP proxy: d3:sdp399:v=0#015#012o=- 0 0 IN IP4 192.168.2.106#015#012s=session#015#012c=IN IP4 192.168.2.106#015#012b=CT:100000#015#012t=0 0#015#012m=audio 30006 RTP/AVP 8 97 96 13#015#012c=IN IP4 10.1.0.127#015#012a=rtpmap:8 PCMA/8000#015#012a=ptime:20#015#012a=label:main-audio#015#012a=x-ssrc-range:91-91#015#012a=x-source:main-audio#015#012a=rtcp-fb:\* x-message app recv:dsh#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:96 telephone-event/8000#015#012a=fmtp:96 0-16#015#012a=rtpmap:13 CN/8000#015#012a=sendrecv#015#012a=rtcp:30007#015#0126:result2:oke
Jul 24 15:18:54 localhost /usr/local/sbin/kamailio[5039]: INFO: <script>: ERJ21 - 183 reply to INVITE to LYNCIT
Jul 24 15:18:54 localhost rtpengine[4945]: Got valid command from 127.0.0.1:47165: answer - { "sdp": "v=0#015#012o=- 0 0 IN IP4 192.168.2.106#015#012s=session#015#012c=IN IP4 192.168.2.106#015#012b=CT:100000#015#012t=0 0#015#012m=audio 33044 RTP/SAVP 8 97 96 13#015#012c=IN IP4 192.168.2.106#015#012a=rtcp:33045#015#012a=sendrecv#015#012a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:ylCL8bd0++YSTxeOKthU+Bmo6ZAVwEfPdxshwVZi|2^31|1:1#015#012a=rtpmap:8 PCMA/8000#015#012a=ptime:20#015#012a=label:main-audio#015#012a=x-ssrc-range:90-90#015#012a=x-source:main-audio#015#012a=rtcp-fb:\* x-message app recv:dsh#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:96 telephone-event/8000#015#012a=fmtp:96 0-16#015#012a=rtpmap:13 CN/8000#015#012", "ICE": "remove", "transport-protocol": "RTP/AVP", "call-id": "YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.", "received-from": [ "IP4", "192.168.2.106" ], "from-tag": "422ab553", "to-tag": "cdbc926be2", "command": "answer" }
Jul 24 15:18:54 localhost rtpengine[4945]: ERJ LOG_ERROR parse crypto 1 31
Jul 24 15:18:54 localhost rtpengine[4945]: ERJ LOG_INFO parse crypto 1 31
Jul 24 15:18:54 localhost rtpengine[4945]: ERJ parse crypto 2 2147483648
Jul 24 15:18:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] Returning to SIP proxy: d3:sdp399:v=0#015#012o=- 0 0 IN IP4 192.168.2.106#015#012s=session#015#012c=IN IP4 192.168.2.106#015#012b=CT:100000#015#012t=0 0#015#012m=audio 30008 RTP/AVP 8 97 96 13#015#012c=IN IP4 10.1.0.127#015#012a=rtpmap:8 PCMA/8000#015#012a=ptime:20#015#012a=label:main-audio#015#012a=x-ssrc-range:90-90#015#012a=x-source:main-audio#015#012a=rtcp-fb:\* x-message app recv:dsh#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:96 telephone-event/8000#015#012a=fmtp:96 0-16#015#012a=rtpmap:13 CN/8000#015#012a=sendrecv#015#012a=rtcp:30009#015#0126:result2:oke
Jul 24 15:18:54 localhost /usr/local/sbin/kamailio[5036]: NOTICE: <script>: Enter main request route
Jul 24 15:18:54 localhost /usr/local/sbin/kamailio[5036]: INFO: <script>: Main request route PRACK
Jul 24 15:18:54 localhost /usr/local/sbin/kamailio[5036]: INFO: <script>: IN_DIALOG_TO_LYNCIT
Jul 24 15:18:54 localhost /usr/local/sbin/kamailio[5036]: INFO: <script>: ERJ08 - IN_DIALOG_TO_LYNCIT PRACK
Jul 24 15:18:54 localhost /usr/local/sbin/kamailio[5036]: INFO: <script>: ERJ10 - IN_DIALOG_TO_LYNCIT NO sdp
Jul 24 15:18:54 localhost /usr/local/sbin/kamailio[5036]: INFO: <script>: ERJ20 - 183 reply to INVITE from LYNCIT
Jul 24 15:18:54 localhost rtpengine[4945]: Got valid command from 127.0.0.1:42187: answer - { "sdp": "v=0#015#012o=Redwood_INX 514876 514876 IN IP4 10.1.0.121#015#012s=Redwood Media Server#015#012c=IN IP4 10.1.0.121#015#012t=0 0#015#012m=audio 19110 RTP/AVP 8 97 101 13#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=rtpmap:13 CN/8000#015#012a=sendrecv#015#012", "ICE": "force", "flags": [ "force", "trust-address" ], "replace": [ "origin", "session-connection" ], "transport-protocol": "RTP/SAVP", "call-id": "2cb67bfe-5a85-4010-8e20-572bd9cd24f6", "received-from": [ "IP4", "10.1.0.119" ], "from-tag": "a5bc7e554", "to-tag": "f242e810", "command": "answer" }
Jul 24 15:18:54 localhost rtpengine[4945]: [2cb67bfe-5a85-4010-8e20-572bd9cd24f6] Returning to SIP proxy: d3:sdp587:v=0#015#012o=Redwood_INX 514876 514876 IN IP4 10.1.0.127#015#012s=Redwood Media Server#015#012c=IN IP4 10.1.0.127#015#012t=0 0#015#012a=ice-lite#015#012m=audio 30002 RTP/SAVP 8 97 101 13#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=rtpmap:13 CN/8000#015#012a=sendrecv#015#012a=rtcp:30003#015#012a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:KpirdRvhc8KepnqsDz5gnbNuDOiUWuIeUsdD1y5i#015#012a=ice-ufrag:xC3Cfqis#015#012a=ice-pwd:CYM7EP5wmggr9X3fL0XGR1dnCgZR#015#012a=candidate:GJzGDWWqDztv0n8z 1 UDP 2130706432 10.1.0.127 30002 typ host#015#012a=candidate:GJzGDWWqDztv0n8z 2 UDP 2130706431 10.1.0.127 30003 typ host#015#0126:result2:oke
Jul 24 15:18:54 localhost /usr/local/sbin/kamailio[5039]: NOTICE: <script>: Enter main request route
Jul 24 15:18:54 localhost /usr/local/sbin/kamailio[5039]: INFO: <script>: Main request route PRACK
Jul 24 15:18:54 localhost /usr/local/sbin/kamailio[5039]: INFO: <script>: IN_DIALOG_FROM_LYNCIT
Jul 24 15:19:02 localhost /usr/local/sbin/kamailio[5036]: INFO: <script>: ERJ21 - 183 reply to INVITE to LYNCIT
Jul 24 15:19:02 localhost rtpengine[4945]: Got valid command from 127.0.0.1:42187: answer - { "sdp": "v=0#015#012o=- 0 0 IN IP4 192.168.2.106#015#012s=session#015#012c=IN IP4 192.168.2.106#015#012b=CT:100000#015#012t=0 0#015#012m=audio 33044 RTP/SAVP 8 97 96 13#015#012c=IN IP4 192.168.2.106#015#012a=rtcp:33045#015#012a=sendrecv#015#012a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:ylCL8bd0++YSTxeOKthU+Bmo6ZAVwEfPdxshwVZi|2^31|1:1#015#012a=rtpmap:8 PCMA/8000#015#012a=ptime:20#015#012a=label:main-audio#015#012a=x-ssrc-range:90-90#015#012a=x-source:main-audio#015#012a=rtcp-fb:\* x-message app recv:dsh#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:96 telephone-event/8000#015#012a=fmtp:96 0-16#015#012a=rtpmap:13 CN/8000#015#012", "ICE": "remove", "transport-protocol": "RTP/AVP", "call-id": "YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.", "received-from": [ "IP4", "192.168.2.106" ], "from-tag": "422ab553", "to-tag": "cdbc926be2", "command": "answer" }
Jul 24 15:19:02 localhost rtpengine[4945]: ERJ LOG_ERROR parse crypto 1 31
Jul 24 15:19:02 localhost rtpengine[4945]: ERJ LOG_INFO parse crypto 1 31
Jul 24 15:19:02 localhost rtpengine[4945]: ERJ parse crypto 2 2147483648
Jul 24 15:19:02 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] Returning to SIP proxy: d3:sdp399:v=0#015#012o=- 0 0 IN IP4 192.168.2.106#015#012s=session#015#012c=IN IP4 192.168.2.106#015#012b=CT:100000#015#012t=0 0#015#012m=audio 30008 RTP/AVP 8 97 96 13#015#012c=IN IP4 10.1.0.127#015#012a=rtpmap:8 PCMA/8000#015#012a=ptime:20#015#012a=label:main-audio#015#012a=x-ssrc-range:90-90#015#012a=x-source:main-audio#015#012a=rtcp-fb:\* x-message app recv:dsh#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:96 telephone-event/8000#015#012a=fmtp:96 0-16#015#012a=rtpmap:13 CN/8000#015#012a=sendrecv#015#012a=rtcp:30009#015#0126:result2:oke
Jul 24 15:19:02 localhost /usr/local/sbin/kamailio[5039]: NOTICE: <script>: Enter main request route
Jul 24 15:19:02 localhost /usr/local/sbin/kamailio[5039]: INFO: <script>: Main request route ACK
Jul 24 15:19:02 localhost /usr/local/sbin/kamailio[5039]: INFO: <script>: IN_DIALOG_TO_LYNCIT
Jul 24 15:19:02 localhost /usr/local/sbin/kamailio[5039]: INFO: <script>: ERJ10 - IN_DIALOG_TO_LYNCIT NO sdp
Jul 24 15:19:02 localhost /usr/local/sbin/kamailio[5036]: INFO: <script>: ERJ20 - 183 reply to INVITE from LYNCIT
Jul 24 15:19:02 localhost rtpengine[4945]: Got valid command from 127.0.0.1:42187: answer - { "sdp": "v=0#015#012o=Redwood_INX 514876 514876 IN IP4 10.1.0.121#015#012s=Redwood Media Server#015#012c=IN IP4 10.1.0.121#015#012t=0 0#015#012m=audio 19110 RTP/AVP 8 97 101 13#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=rtpmap:13 CN/8000#015#012a=sendrecv#015#012", "ICE": "force", "flags": [ "force", "trust-address" ], "replace": [ "origin", "session-connection" ], "transport-protocol": "RTP/SAVP", "call-id": "2cb67bfe-5a85-4010-8e20-572bd9cd24f6", "received-from": [ "IP4", "10.1.0.119" ], "from-tag": "a5bc7e554", "to-tag": "f242e810", "command": "answer" }
Jul 24 15:19:02 localhost rtpengine[4945]: [2cb67bfe-5a85-4010-8e20-572bd9cd24f6] Returning to SIP proxy: d3:sdp587:v=0#015#012o=Redwood_INX 514876 514876 IN IP4 10.1.0.127#015#012s=Redwood Media Server#015#012c=IN IP4 10.1.0.127#015#012t=0 0#015#012a=ice-lite#015#012m=audio 30002 RTP/SAVP 8 97 101 13#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=rtpmap:13 CN/8000#015#012a=sendrecv#015#012a=rtcp:30003#015#012a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:KpirdRvhc8KepnqsDz5gnbNuDOiUWuIeUsdD1y5i#015#012a=ice-ufrag:xC3Cfqis#015#012a=ice-pwd:CYM7EP5wmggr9X3fL0XGR1dnCgZR#015#012a=candidate:GJzGDWWqDztv0n8z 1 UDP 2130706432 10.1.0.127 30002 typ host#015#012a=candidate:GJzGDWWqDztv0n8z 2 UDP 2130706431 10.1.0.127 30003 typ host#015#0126:result2:oke
Jul 24 15:19:02 localhost /usr/local/sbin/kamailio[5039]: NOTICE: <script>: Enter main request route
Jul 24 15:19:02 localhost /usr/local/sbin/kamailio[5039]: INFO: <script>: Main request route ACK
Jul 24 15:19:02 localhost /usr/local/sbin/kamailio[5039]: INFO: <script>: IN_DIALOG_FROM_LYNCIT
Jul 24 15:19:02 localhost /usr/local/sbin/kamailio[5039]: NOTICE: <script>: Enter main request route
Jul 24 15:19:02 localhost /usr/local/sbin/kamailio[5039]: INFO: <script>: Main request route BYE
Jul 24 15:19:02 localhost /usr/local/sbin/kamailio[5039]: INFO: <script>: IN_DIALOG_FROM_LYNCIT
Jul 24 15:19:03 localhost /usr/local/sbin/kamailio[5039]: NOTICE: <script>: Enter main request route
Jul 24 15:19:03 localhost /usr/local/sbin/kamailio[5039]: INFO: <script>: Main request route BYE
Jul 24 15:19:03 localhost /usr/local/sbin/kamailio[5039]: INFO: <script>: IN_DIALOG_TO_LYNCIT
Jul 24 15:19:03 localhost /usr/local/sbin/kamailio[5039]: INFO: <script>: ERJ10 - IN_DIALOG_TO_LYNCIT NO sdp
Jul 24 15:19:07 localhost /usr/local/sbin/kamailio[5036]: NOTICE: <script>: Enter main request route
Jul 24 15:19:07 localhost /usr/local/sbin/kamailio[5036]: INFO: <script>: Main request route OPTIONS
Jul 24 15:19:07 localhost /usr/local/sbin/kamailio[5036]: NOTICE: <script>: Enter main request route
Jul 24 15:19:07 localhost /usr/local/sbin/kamailio[5036]: INFO: <script>: Main request route OPTIONS
Jul 24 15:19:09 localhost rtpengine[4945]: Closing call branch due to timeout
Jul 24 15:19:09 localhost rtpengine[4945]: [2cb67bfe-5a85-4010-8e20-572bd9cd24f6] Final packet stats:
Jul 24 15:19:09 localhost rtpengine[4945]: [2cb67bfe-5a85-4010-8e20-572bd9cd24f6] --- Tag 'f242e810', created 1:00 ago, in dialogue with 'a5bc7e554'
Jul 24 15:19:09 localhost rtpengine[4945]: [2cb67bfe-5a85-4010-8e20-572bd9cd24f6] ------ Media #1, port 30002 <>   192.168.2.106:33042, 0 p, 0 b, 0 e
Jul 24 15:19:09 localhost rtpengine[4945]: [2cb67bfe-5a85-4010-8e20-572bd9cd24f6] ------ Media #1, port 30003 <>   192.168.2.106:33043 (RTCP), 0 p, 0 b, 0 e
Jul 24 15:19:09 localhost rtpengine[4945]: [2cb67bfe-5a85-4010-8e20-572bd9cd24f6] --- Tag 'a5bc7e554', created 1:00 ago, in dialogue with 'f242e810'
Jul 24 15:19:09 localhost rtpengine[4945]: [2cb67bfe-5a85-4010-8e20-572bd9cd24f6] ------ Media #1, port 30000 <>      10.1.0.121:19110, 0 p, 0 b, 0 e
Jul 24 15:19:09 localhost rtpengine[4945]: [2cb67bfe-5a85-4010-8e20-572bd9cd24f6] ------ Media #1, port 30001 <>      10.1.0.121:19111 (RTCP), 0 p, 0 b, 0 e
Jul 24 15:19:54 localhost rtpengine[4945]: Closing call branch due to timeout
Jul 24 15:19:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] Final packet stats:
Jul 24 15:19:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] --- Tag 'cdbc926be2', created 1:00 ago, in dialogue with '422ab553'
Jul 24 15:19:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] ------ Media #1, port 30008 <>            [::]:0    , 0 p, 0 b, 0 e
Jul 24 15:19:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] ------ Media #1, port 30009 <>            [::]:0     (RTCP), 0 p, 0 b, 0 e
Jul 24 15:19:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] --- Tag 'ad508ba5ae', created 1:00 ago, in dialogue with '422ab553'
Jul 24 15:19:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] ------ Media #1, port 30006 <>      10.1.0.121:19130, 0 p, 0 b, 0 e
Jul 24 15:19:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] ------ Media #1, port 30007 <>      10.1.0.121:19131 (RTCP), 0 p, 0 b, 0 e
Jul 24 15:19:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] --- Tag '422ab553', created 1:00 ago, in dialogue with 'cdbc926be2'
Jul 24 15:19:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] ------ Media #1, port 30004 <>   192.168.2.106:33044, 0 p, 0 b, 0 e
Jul 24 15:19:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] ------ Media #1, port 30005 <>   192.168.2.106:33045 (RTCP), 0 p, 0 b, 0 e

from rtpengine.

rfuchs commented on June 24, 2024

Sorry but this doesn't contain any useful information. The log you posted doesn't contain any calls.

from rtpengine.

edjames99 commented on June 24, 2024

There are two calls in the log file as follows:

First Call - Search for "OUT_DIALOG_FROM_LYNCIT" - some call details:
Jul 24 15:18:09 localhost rtpengine[4945]: Got valid command from 127.0.0.1:42187: offer...
call-id = 2cb67bfe-5a85-4010-8e20-572bd9cd24f6
"received-from": [ "IP4", "192.168.2.106" ]
result2:oke

Second Call - Search for "OUT_DIALOG_TO_LYNCIT - some call details:
Jul 24 15:18:54 localhost rtpengine[4945]: Got valid command from 127.0.0.1:42187: offer...
"call-id": "YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.
"received-from": [ "IP4", "10.1.0.119" ]
result2:oke

I assume at this point rtpengine has knowledge of both calls (the SRTP from 192.168.2.106 and the RTP from 10.1.0.119) as it has modified the sdp offer in both SIP INVITE messages. What were you looking for in the log ? What log entries were you expecting to see that weren't there ?

from rtpengine.

rfuchs commented on June 24, 2024

Yes, those would be the lines. Search the page yourself, they don't appear in what you posted.

from rtpengine.

edjames99 commented on June 24, 2024

I think you have to hit the Edit Comment pencil icon then do a select all and then paste to see the entire contents of the post.

from rtpengine.

rfuchs commented on June 24, 2024

Ah yes, you're right. Silly github, truncating comments like that. Reproducing the relevant log lines here, reformatted for clarity:

Jul 24 15:18:09 localhost rtpengine[4945]: Got valid command from 127.0.0.1:42187: offer - { "sdp": "v=0
o=- 0 0 IN IP4 192.168.2.106
s=session
c=IN IP4 192.168.2.106
b=CT:100000
t=0 0
m=audio 33042 RTP/SAVP 0 8 97 101 13
c=IN IP4 192.168.2.106
a=rtcp:33043
a=sendrecv
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:yTsMgQAYfsg5Eq8u9LJLKOcIafzyzK19UwssmASF|2^31|1:1
a=crypto:2 AES_CM_128_HMAC_SHA1_80 inline:A1Jzi0OLDgUB6l8uXfp7vAyNTzb4w8CcwjRrPS7G|2^31
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=label:main-audio
a=rtcp-rsize
a=x-ssrc-range:89-89
a=x-source:main-audio
a=rtcp-fb:* x-message app recv:dsh
a=rtpmap:97 red/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
", "ICE": "remove", "flags": [ "force", "trust-address" ], "replace": [ "origin", "session-connection" ], "transport-protocol": "RTP/AVP", "call-id": "2cb67bfe-5a85-4010-8e20-572bd9cd24f6", "received-from": [ "IP4", "192.168.2.106" ], "from-tag": "a5bc7e554", "command": "offer" }




Jul 24 15:18:09 localhost rtpengine[4945]: [2cb67bfe-5a85-4010-8e20-572bd9cd24f6] Returning to SIP proxy: d3:sdp422:v=0
o=- 0 0 IN IP4 10.1.0.127
s=session
c=IN IP4 10.1.0.127
b=CT:100000
t=0 0
m=audio 30000 RTP/AVP 0 8 97 101 13
c=IN IP4 10.1.0.127
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=label:main-audio
a=rtcp-rsize
a=x-ssrc-range:89-89
a=x-source:main-audio
a=rtcp-fb:* x-message app recv:dsh
a=rtpmap:97 red/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=sendrecv
a=rtcp:30001
6:result2:oke




Jul 24 15:18:54 localhost rtpengine[4945]: Got valid command from 127.0.0.1:42187: offer - { "sdp": "v=0
o=Redwood_INX 515320 515320 IN IP4 10.1.0.121
s=Redwood Media Server
c=IN IP4 10.1.0.121
t=0 0
m=audio 19130 RTP/AVP 8 97 96 13
a=rtpmap:8 PCMA/8000
a=rtpmap:97 red/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-16
a=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv
a=rtcp:19131
a=label:main-audio
", "ICE": "force", "flags": [ "force", "trust-address" ], "replace": [ "origin", "session-connection" ], "transport-protocol": "RTP/SAVP", "call-id": "YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.", "received-from": [ "IP4", "10.1.0.119" ], "from-tag": "422ab553", "command": "offer" }




Jul 24 15:18:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] Returning to SIP proxy: d3:sdp714:v=0
o=Redwood_INX 515320 515320 IN IP4 10.1.0.127
s=Redwood Media Server
c=IN IP4 10.1.0.127
t=0 0
a=ice-lite
m=audio 30004 RTP/SAVP 8 97 96 13
a=rtpmap:8 PCMA/8000
a=rtpmap:97 red/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-16
a=rtpmap:13 CN/8000
a=ptime:20
a=label:main-audio
a=sendrecv
a=rtcp:30005
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:45ddxkGAgIgJY7MlhjUQUDYLpiWyWuG/GN7FY6rr
a=setup:actpass
a=fingerprint:sha-1 6C:C3:2F:5F:72:6E:EE:76:15:7E:72:87:29:38:80:4F:BD:03:71:62
a=ice-ufrag:0xOvNbVt
a=ice-pwd:7SyAP39k1JtcwdUzJWwe7oB7TpDG
a=candidate:GJzGDWWqDztv0n8z 1 UDP 2130706432 10.1.0.127 30004 typ host
a=candidate:GJzGDWWqDztv0n8z 2 UDP 2130706431 10.1.0.127 30005 typ host
6:result2:oke




Jul 24 15:18:54 localhost rtpengine[4945]: Got valid command from 127.0.0.1:47165: answer - { "sdp": "v=0
o=- 0 0 IN IP4 192.168.2.106
s=session
c=IN IP4 192.168.2.106
b=CT:100000
t=0 0
m=audio 33488 RTP/SAVP 8 97 96 13
c=IN IP4 192.168.2.106
a=rtcp:33489
a=sendrecv
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:mMRsrZmELQh9fqusFxkwdue5wSmrLnMCRLngxH0A|2^31|1:1
a=rtpmap:8 PCMA/8000
a=ptime:20
a=label:main-audio
a=x-ssrc-range:91-91
a=x-source:main-audio
a=rtcp-fb:* x-message app recv:dsh
a=rtpmap:97 red/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-16
a=rtpmap:13 CN/8000
", "ICE": "remove", "transport-protocol": "RTP/AVP", "call-id": "YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.", "received-from": [ "IP4", "192.168.2.106" ], "from-tag": "422ab553", "to-tag": "ad508ba5ae", "command": "answer" }




Jul 24 15:18:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] Returning to SIP proxy: d3:sdp399:v=0
o=- 0 0 IN IP4 192.168.2.106
s=session
c=IN IP4 192.168.2.106
b=CT:100000
t=0 0
m=audio 30006 RTP/AVP 8 97 96 13
c=IN IP4 10.1.0.127
a=rtpmap:8 PCMA/8000
a=ptime:20
a=label:main-audio
a=x-ssrc-range:91-91
a=x-source:main-audio
a=rtcp-fb:* x-message app recv:dsh
a=rtpmap:97 red/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-16
a=rtpmap:13 CN/8000
a=sendrecv
a=rtcp:30007
6:result2:oke





Jul 24 15:18:54 localhost rtpengine[4945]: Got valid command from 127.0.0.1:47165: answer - { "sdp": "v=0
o=- 0 0 IN IP4 192.168.2.106
s=session
c=IN IP4 192.168.2.106
b=CT:100000
t=0 0
m=audio 33044 RTP/SAVP 8 97 96 13
c=IN IP4 192.168.2.106
a=rtcp:33045
a=sendrecv
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:ylCL8bd0++YSTxeOKthU+Bmo6ZAVwEfPdxshwVZi|2^31|1:1
a=rtpmap:8 PCMA/8000
a=ptime:20
a=label:main-audio
a=x-ssrc-range:90-90
a=x-source:main-audio
a=rtcp-fb:* x-message app recv:dsh
a=rtpmap:97 red/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-16
a=rtpmap:13 CN/8000
", "ICE": "remove", "transport-protocol": "RTP/AVP", "call-id": "YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.", "received-from": [ "IP4", "192.168.2.106" ], "from-tag": "422ab553", "to-tag": "cdbc926be2", "command": "answer" }





Jul 24 15:18:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] Returning to SIP proxy: d3:sdp399:v=0
o=- 0 0 IN IP4 192.168.2.106
s=session
c=IN IP4 192.168.2.106
b=CT:100000
t=0 0
m=audio 30008 RTP/AVP 8 97 96 13
c=IN IP4 10.1.0.127
a=rtpmap:8 PCMA/8000
a=ptime:20
a=label:main-audio
a=x-ssrc-range:90-90
a=x-source:main-audio
a=rtcp-fb:* x-message app recv:dsh
a=rtpmap:97 red/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-16
a=rtpmap:13 CN/8000
a=sendrecv
a=rtcp:30009
6:result2:oke





Jul 24 15:18:54 localhost rtpengine[4945]: Got valid command from 127.0.0.1:42187: answer - { "sdp": "v=0
o=Redwood_INX 514876 514876 IN IP4 10.1.0.121
s=Redwood Media Server
c=IN IP4 10.1.0.121
t=0 0
m=audio 19110 RTP/AVP 8 97 101 13
a=rtpmap:8 PCMA/8000
a=rtpmap:97 red/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=sendrecv
", "ICE": "force", "flags": [ "force", "trust-address" ], "replace": [ "origin", "session-connection" ], "transport-protocol": "RTP/SAVP", "call-id": "2cb67bfe-5a85-4010-8e20-572bd9cd24f6", "received-from": [ "IP4", "10.1.0.119" ], "from-tag": "a5bc7e554", "to-tag": "f242e810", "command": "answer" }





Jul 24 15:18:54 localhost rtpengine[4945]: [2cb67bfe-5a85-4010-8e20-572bd9cd24f6] Returning to SIP proxy: d3:sdp587:v=0
o=Redwood_INX 514876 514876 IN IP4 10.1.0.127
s=Redwood Media Server
c=IN IP4 10.1.0.127
t=0 0
a=ice-lite
m=audio 30002 RTP/SAVP 8 97 101 13
a=rtpmap:8 PCMA/8000
a=rtpmap:97 red/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=sendrecv
a=rtcp:30003
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:KpirdRvhc8KepnqsDz5gnbNuDOiUWuIeUsdD1y5i
a=ice-ufrag:xC3Cfqis
a=ice-pwd:CYM7EP5wmggr9X3fL0XGR1dnCgZR
a=candidate:GJzGDWWqDztv0n8z 1 UDP 2130706432 10.1.0.127 30002 typ host
a=candidate:GJzGDWWqDztv0n8z 2 UDP 2130706431 10.1.0.127 30003 typ host
6:result2:oke





Jul 24 15:19:02 localhost rtpengine[4945]: Got valid command from 127.0.0.1:42187: answer - { "sdp": "v=0
o=- 0 0 IN IP4 192.168.2.106
s=session
c=IN IP4 192.168.2.106
b=CT:100000
t=0 0
m=audio 33044 RTP/SAVP 8 97 96 13
c=IN IP4 192.168.2.106
a=rtcp:33045
a=sendrecv
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:ylCL8bd0++YSTxeOKthU+Bmo6ZAVwEfPdxshwVZi|2^31|1:1
a=rtpmap:8 PCMA/8000
a=ptime:20
a=label:main-audio
a=x-ssrc-range:90-90
a=x-source:main-audio
a=rtcp-fb:* x-message app recv:dsh
a=rtpmap:97 red/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-16
a=rtpmap:13 CN/8000
", "ICE": "remove", "transport-protocol": "RTP/AVP", "call-id": "YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.", "received-from": [ "IP4", "192.168.2.106" ], "from-tag": "422ab553", "to-tag": "cdbc926be2", "command": "answer" }





Jul 24 15:19:02 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] Returning to SIP proxy: d3:sdp399:v=0
o=- 0 0 IN IP4 192.168.2.106
s=session
c=IN IP4 192.168.2.106
b=CT:100000
t=0 0
m=audio 30008 RTP/AVP 8 97 96 13
c=IN IP4 10.1.0.127
a=rtpmap:8 PCMA/8000
a=ptime:20
a=label:main-audio
a=x-ssrc-range:90-90
a=x-source:main-audio
a=rtcp-fb:* x-message app recv:dsh
a=rtpmap:97 red/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-16
a=rtpmap:13 CN/8000
a=sendrecv
a=rtcp:30009
6:result2:oke





Jul 24 15:19:02 localhost rtpengine[4945]: Got valid command from 127.0.0.1:42187: answer - { "sdp": "v=0
o=Redwood_INX 514876 514876 IN IP4 10.1.0.121
s=Redwood Media Server
c=IN IP4 10.1.0.121
t=0 0
m=audio 19110 RTP/AVP 8 97 101 13
a=rtpmap:8 PCMA/8000
a=rtpmap:97 red/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=sendrecv
", "ICE": "force", "flags": [ "force", "trust-address" ], "replace": [ "origin", "session-connection" ], "transport-protocol": "RTP/SAVP", "call-id": "2cb67bfe-5a85-4010-8e20-572bd9cd24f6", "received-from": [ "IP4", "10.1.0.119" ], "from-tag": "a5bc7e554", "to-tag": "f242e810", "command": "answer" }





Jul 24 15:19:02 localhost rtpengine[4945]: [2cb67bfe-5a85-4010-8e20-572bd9cd24f6] Returning to SIP proxy: d3:sdp587:v=0
o=Redwood_INX 514876 514876 IN IP4 10.1.0.127
s=Redwood Media Server
c=IN IP4 10.1.0.127
t=0 0
a=ice-lite
m=audio 30002 RTP/SAVP 8 97 101 13
a=rtpmap:8 PCMA/8000
a=rtpmap:97 red/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=sendrecv
a=rtcp:30003
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:KpirdRvhc8KepnqsDz5gnbNuDOiUWuIeUsdD1y5i
a=ice-ufrag:xC3Cfqis
a=ice-pwd:CYM7EP5wmggr9X3fL0XGR1dnCgZR
a=candidate:GJzGDWWqDztv0n8z 1 UDP 2130706432 10.1.0.127 30002 typ host
a=candidate:GJzGDWWqDztv0n8z 2 UDP 2130706431 10.1.0.127 30003 typ host
6:result2:oke

from rtpengine.

rfuchs commented on June 24, 2024

So we have...

First call, 2cb67bfe-5a85-4010-8e20-572bd9cd24f6

[SRTP] 192.168.2.106:33042 <> 30002 / 30000 <> 10.1.0.121:19110 [RTP]

IOW, packets received on port 30000 are sent out on port 30002 to side A, and packets received on port 30002 are sent out on port 30000 to side B.

Second call, YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU

[RTP] 10.1.0.121:19130 <> 30006 / 30004 <> 192.168.2.106:33488 [SRTP]
then
[RTP] 10.1.0.121:19130 <> 30008 / 30004 <> 192.168.2.106:33044 [SRTP]

All this looks fine. However, the final packet stats don't look so good. Both calls are terminated due to timeout:

Jul 24 15:19:09 localhost rtpengine[4945]: Closing call branch due to timeout
Jul 24 15:19:09 localhost rtpengine[4945]: [2cb67bfe-5a85-4010-8e20-572bd9cd24f6] Final packet stats:
Jul 24 15:19:09 localhost rtpengine[4945]: [2cb67bfe-5a85-4010-8e20-572bd9cd24f6] --- Tag 'f242e810', created 1:00 ago, in dialogue with 'a5bc7e554'
Jul 24 15:19:09 localhost rtpengine[4945]: [2cb67bfe-5a85-4010-8e20-572bd9cd24f6] ------ Media #1, port 30002 <>   192.168.2.106:33042, 0 p, 0 b, 0 e
Jul 24 15:19:09 localhost rtpengine[4945]: [2cb67bfe-5a85-4010-8e20-572bd9cd24f6] ------ Media #1, port 30003 <>   192.168.2.106:33043 (RTCP), 0 p, 0 b, 0 e
Jul 24 15:19:09 localhost rtpengine[4945]: [2cb67bfe-5a85-4010-8e20-572bd9cd24f6] --- Tag 'a5bc7e554', created 1:00 ago, in dialogue with 'f242e810'
Jul 24 15:19:09 localhost rtpengine[4945]: [2cb67bfe-5a85-4010-8e20-572bd9cd24f6] ------ Media #1, port 30000 <>      10.1.0.121:19110, 0 p, 0 b, 0 e
Jul 24 15:19:09 localhost rtpengine[4945]: [2cb67bfe-5a85-4010-8e20-572bd9cd24f6] ------ Media #1, port 30001 <>      10.1.0.121:19111 (RTCP), 0 p, 0 b, 0 e
Jul 24 15:19:54 localhost rtpengine[4945]: Closing call branch due to timeout
Jul 24 15:19:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] Final packet stats:
Jul 24 15:19:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] --- Tag 'cdbc926be2', created 1:00 ago, in dialogue with '422ab553'
Jul 24 15:19:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] ------ Media #1, port 30008 <>            [::]:0    , 0 p, 0 b, 0 e
Jul 24 15:19:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] ------ Media #1, port 30009 <>            [::]:0     (RTCP), 0 p, 0 b, 0 e
Jul 24 15:19:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] --- Tag 'ad508ba5ae', created 1:00 ago, in dialogue with '422ab553'
Jul 24 15:19:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] ------ Media #1, port 30006 <>      10.1.0.121:19130, 0 p, 0 b, 0 e
Jul 24 15:19:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] ------ Media #1, port 30007 <>      10.1.0.121:19131 (RTCP), 0 p, 0 b, 0 e
Jul 24 15:19:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] --- Tag '422ab553', created 1:00 ago, in dialogue with 'cdbc926be2'
Jul 24 15:19:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] ------ Media #1, port 30004 <>   192.168.2.106:33044, 0 p, 0 b, 0 e
Jul 24 15:19:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] ------ Media #1, port 30005 <>   192.168.2.106:33045 (RTCP), 0 p, 0 b, 0 e

And all packet stats are zero. This means that rtpengine has never seen any packets coming in on any of these ports. My first guess would be an iptables packet filter. Otherwise perhaps an IP/routing configuration issue? Or possibly an overlap in UDP port ranges with something else that has the same ports open (unlikely).

from rtpengine.

edjames99 commented on June 24, 2024

Hi Richard,

      Thanks, it’s really useful to know that the rtpengine didn’t receive any of the packets. I’m now on holiday until 11th August but I’ll pick this up again then.

Thanks for your help.

From: Richard Fuchs [mailto:[email protected]]
Sent: 25 July 2014 19:42
To: sipwise/rtpengine
Cc: edjames99
Subject: Re: [rtpengine] No RTP/SRTP Sent (#12)

So we have...

First call, 2cb67bfe-5a85-4010-8e20-572bd9cd24f6

[SRTP] 192.168.2.106:33042 <> 30002 / 30000 <> 10.1.0.121:19110 [RTP]

IOW, packets received on port 30000 are sent out on port 30002 to side A, and packets received on port 30002 are sent out on port 30000 to side B.

Second call, YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU

[RTP] 10.1.0.121:19130 <> 30006 / 30004 <> 192.168.2.106:33488 [SRTP]
then
[RTP] 10.1.0.121:19130 <> 30008 / 30004 <> 192.168.2.106:33044 [SRTP]

All this looks fine. However, the final packet stats don't look so good. Both calls are terminated due to timeout:

Jul 24 15:19:09 localhost rtpengine[4945]: Closing call branch due to timeout
Jul 24 15:19:09 localhost rtpengine[4945]: [2cb67bfe-5a85-4010-8e20-572bd9cd24f6] Final packet stats:
Jul 24 15:19:09 localhost rtpengine[4945]: [2cb67bfe-5a85-4010-8e20-572bd9cd24f6] --- Tag 'f242e810', created 1:00 ago, in dialogue with 'a5bc7e554'
Jul 24 15:19:09 localhost rtpengine[4945]: [2cb67bfe-5a85-4010-8e20-572bd9cd24f6] ------ Media #1, port 30002 <> 192.168.2.106:33042, 0 p, 0 b, 0 e
Jul 24 15:19:09 localhost rtpengine[4945]: [2cb67bfe-5a85-4010-8e20-572bd9cd24f6] ------ Media #1, port 30003 <> 192.168.2.106:33043 (RTCP), 0 p, 0 b, 0 e
Jul 24 15:19:09 localhost rtpengine[4945]: [2cb67bfe-5a85-4010-8e20-572bd9cd24f6] --- Tag 'a5bc7e554', created 1:00 ago, in dialogue with 'f242e810'
Jul 24 15:19:09 localhost rtpengine[4945]: [2cb67bfe-5a85-4010-8e20-572bd9cd24f6] ------ Media #1, port 30000 <> 10.1.0.121:19110, 0 p, 0 b, 0 e
Jul 24 15:19:09 localhost rtpengine[4945]: [2cb67bfe-5a85-4010-8e20-572bd9cd24f6] ------ Media #1, port 30001 <> 10.1.0.121:19111 (RTCP), 0 p, 0 b, 0 e
Jul 24 15:19:54 localhost rtpengine[4945]: Closing call branch due to timeout
Jul 24 15:19:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] Final packet stats:
Jul 24 15:19:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] --- Tag 'cdbc926be2', created 1:00 ago, in dialogue with '422ab553'
Jul 24 15:19:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] ------ Media #1, port 30008 <> [::]:0 , 0 p, 0 b, 0 e
Jul 24 15:19:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] ------ Media #1, port 30009 <> [::]:0 (RTCP), 0 p, 0 b, 0 e
Jul 24 15:19:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] --- Tag 'ad508ba5ae', created 1:00 ago, in dialogue with '422ab553'
Jul 24 15:19:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] ------ Media #1, port 30006 <> 10.1.0.121:19130, 0 p, 0 b, 0 e
Jul 24 15:19:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] ------ Media #1, port 30007 <> 10.1.0.121:19131 (RTCP), 0 p, 0 b, 0 e
Jul 24 15:19:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] --- Tag '422ab553', created 1:00 ago, in dialogue with 'cdbc926be2'
Jul 24 15:19:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] ------ Media #1, port 30004 <> 192.168.2.106:33044, 0 p, 0 b, 0 e
Jul 24 15:19:54 localhost rtpengine[4945]: [YjFhY2Q5OTUzMGVmM2RkMDRkNDI1NzNkYzg0YTM3NzU.] ------ Media #1, port 30005 <> 192.168.2.106:33045 (RTCP), 0 p, 0 b, 0 e

—
Reply to this email directly or view it on GitHub #12 (comment) . https://github.com/notifications/beacon/4895891__eyJzY29wZSI6Ik5ld3NpZXM6QmVhY29uIiwiZXhwaXJlcyI6MTcyMTkzMjkwMywiZGF0YSI6eyJpZCI6Mzc3NzgzMDV9fQ==--aa1230e84d6f506678a7f31653703d84c1e06409.gif

from rtpengine.

edjames99 commented on June 24, 2024

Hi Richard,
Thanks very much for your help, this lack of packets was an ip tables issue which is now fixed. I'm now getting some new errors relating to the call leg which is outbound from RTPEngine, I believe the call leg inbound to RTPEngine is working fine.
I've included the full log file below but I suspect that the errors are due to a failure to negotiate the crypto suite for the outbound leg and the only difference between the crypto attribute on the inbound sdp offer and the outbound sdp offer seems to be that the RTPEngine doesn't include the lifetime and the MKI in the crypto attribute in an outbound offer so:

Offer inbound to RTPEngine:
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:vv8e7tkaWbcILGtwJKXLVI+GlklTLAnI/A4E/HMk|2^31|1:1
a=crypto:2 AES_CM_128_HMAC_SHA1_80 inline:2nCSsIhNJaAc6ZH+r76Tk0RsdeVgpmcRr99fMB+W|2^31

Offer outbound from RTPEngine (no lifetime or MKI):
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:/UjhTmkmsnkeKJ4FJFQTgrJ/xeEsphDDYclGM

It's then saying later on in the logs that SRTP and SRTCP output required but there's no crypto suite agreed. Do you think this could be the cause ? If so where in the code can I make a change which will write these fields out into the message ? The __generate_crypto function already has a lifetime for SRTP and SRTCP (I made it use &crypto_suites[0] to make sure of this) but it doesn't come out in the message.

Thanks for your help Richard, it's much appreciated. The full log:

Aug 20 15:39:13 localhost rtpengine[16796]: Generating new DTLS certificate
Aug 20 15:39:13 localhost rtpengine[16797]: Startup complete, version undefined
Aug 20 15:39:20 localhost /usr/local/sbin/kamailio[16455]: NOTICE: <script>: Enter main request route
Aug 20 15:39:20 localhost /usr/local/sbin/kamailio[16455]: INFO: <script>: Main request route OPTIONS
Aug 20 15:39:20 localhost /usr/local/sbin/kamailio[16456]: NOTICE: <script>: Enter main request route
Aug 20 15:39:20 localhost /usr/local/sbin/kamailio[16456]: INFO: <script>: Main request route OPTIONS
Aug 20 15:39:22 localhost /usr/local/sbin/kamailio[16455]: NOTICE: <script>: Enter main request route
Aug 20 15:39:22 localhost /usr/local/sbin/kamailio[16455]: INFO: <script>: Main request route INVITE
Aug 20 15:39:22 localhost /usr/local/sbin/kamailio[16455]: INFO: <script>: OUT_DIALOG_FROM_LYNCIT
Aug 20 15:39:22 localhost rtpengine[16797]: Got valid command from 127.0.0.1:52802: offer - { "sdp": "v=0#015#012o=- 0 0 IN IP4 192.168.2.106#015#012s=session#015#012c=IN IP4 192.168.2.106#015#012b=CT:100000#015#012t=0 0#015#012m=audio 33042 RTP/SAVP 0 8 97 101 13#015#012c=IN IP4 192.168.2.106#015#012a=rtcp:33043#015#012a=sendrecv#015#012a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:vv8e7tkaWbcILGtwJKXLVI+GlklTLAnI/A4E/HMk|2^31|1:1#015#012a=crypto:2 AES_CM_128_HMAC_SHA1_80 inline:2nCSsIhNJaAc6ZH+r76Tk0RsdeVgpmcRr99fMB+W|2^31#015#012a=rtpmap:0 PCMU/8000#015#012a=rtpmap:8 PCMA/8000#015#012a=label:main-audio#015#012a=rtcp-rsize#015#012a=x-ssrc-range:48-48#015#012a=x-source:main-audio#015#012a=rtcp-fb:* x-message app recv:dsh#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=rtpmap:13 CN/8000#015#012", "ICE": "remove", "flags": [ "force", "trust-address" ], "replace": [ "origin", "session-connection" ], "transport-protocol": "RTP/AVP", "call-id": "87e8d333-7ecb-4ded-9aa6-59cd0aa7e4b4", "received-from": [ "IP4", "192.168.2.106" ], "from-tag": "914d1ecd9", "command": "offer" }
Aug 20 15:39:22 localhost rtpengine[16797]: ERJ LOG_ERROR parse crypto 1 31
Aug 20 15:39:22 localhost rtpengine[16797]: ERJ LOG_INFO parse crypto 1 31
Aug 20 15:39:22 localhost rtpengine[16797]: ERJ parse crypto 2 2147483648
Aug 20 15:39:22 localhost rtpengine[16797]: ERJ LOG_ERROR parse crypto 1 31
Aug 20 15:39:22 localhost rtpengine[16797]: ERJ LOG_INFO parse crypto 1 31
Aug 20 15:39:22 localhost rtpengine[16797]: ERJ parse crypto 2 2147483648
Aug 20 15:39:22 localhost rtpengine[16797]: [87e8d333-7ecb-4ded-9aa6-59cd0aa7e4b4] Creating new call
Aug 20 15:39:22 localhost rtpengine[16797]: [87e8d333-7ecb-4ded-9aa6-59cd0aa7e4b4] Returning to SIP proxy: d3:sdp422:v=0#015#012o=- 0 0 IN IP4 10.1.0.127#015#012s=session#015#012c=IN IP4 10.1.0.127#015#012b=CT:100000#015#012t=0 0#015#012m=audio 30000 RTP/AVP 0 8 97 101 13#015#012c=IN IP4 10.1.0.127#015#012a=rtpmap:0 PCMU/8000#015#012a=rtpmap:8 PCMA/8000#015#012a=label:main-audio#015#012a=rtcp-rsize#015#012a=x-ssrc-range:48-48#015#012a=x-source:main-audio#015#012a=rtcp-fb:* x-message app recv:dsh#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=rtpmap:13 CN/8000#015#012a=sendrecv#015#012a=rtcp:30001#015#0126:result2:oke
Aug 20 15:39:23 localhost /usr/local/sbin/kamailio[16456]: NOTICE: <script>: Enter main request route
Aug 20 15:39:23 localhost /usr/local/sbin/kamailio[16456]: INFO: <script>: Main request route INVITE
Aug 20 15:39:23 localhost /usr/local/sbin/kamailio[16456]: INFO: <script>: OUT_DIALOG_TO_LYNCIT
Aug 20 15:39:23 localhost /usr/local/sbin/kamailio[16456]: INFO: <script>: sending to 192.168.2.106:5076 ERJ01
Aug 20 15:39:23 localhost /usr/local/sbin/kamailio[16456]: INFO: <script>: ERJ05 - out dialog to lyncit
Aug 20 15:39:23 localhost /usr/local/sbin/kamailio[16456]: INFO: <script>: ERJ06 - out dialog to lyncit INVITE
Aug 20 15:39:23 localhost /usr/local/sbin/kamailio[16456]: INFO: <script>: ERJ07 - out dialog to lyncit INVITE sdp
Aug 20 15:39:23 localhost rtpengine[16797]: Got valid command from 127.0.0.1:52063: offer - { "sdp": "v=0#015#012o=Redwood_INX 527646 527646 IN IP4 10.1.0.121#015#012s=Redwood Media Server#015#012c=IN IP4 10.1.0.121#015#012t=0 0#015#012m=audio 19620 RTP/AVP 8 97 96 13#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:96 telephone-event/8000#015#012a=fmtp:96 0-16#015#012a=rtpmap:13 CN/8000#015#012a=ptime:20#015#012a=sendrecv#015#012a=rtcp:19621#015#012a=label:main-audio#015#012", "ICE": "force", "flags": [ "force", "trust-address" ], "replace": [ "origin", "session-connection" ], "transport-protocol": "RTP/SAVP", "call-id": "NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA.", "received-from": [ "IP4", "10.1.0.119" ], "from-tag": "37030554", "command": "offer" }
Aug 20 15:39:23 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA.] Creating new call
Aug 20 15:39:23 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA.] Returning to SIP proxy: d3:sdp714:v=0#015#012o=Redwood_INX 527646 527646 IN IP4 10.1.0.127#015#012s=Redwood Media Server#015#012c=IN IP4 10.1.0.127#015#012t=0 0#015#012a=ice-lite#015#012m=audio 30004 RTP/SAVP 8 97 96 13#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:96 telephone-event/8000#015#012a=fmtp:96 0-16#015#012a=rtpmap:13 CN/8000#015#012a=ptime:20#015#012a=label:main-audio#015#012a=sendrecv#015#012a=rtcp:30005#015#012a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:/UjhTmkmsnkeKJ4FJFQTgrJ/xeEsphDDYclGM/Jk#015#012a=setup:actpass#015#012a=fingerprint:sha-1 4E:C1:69:F1:80:7C:91:0B:D2:D7:86:A4:A6:A3:3F:05:89:A2:63:B0#015#012a=ice-ufrag:edMpJ3Iu#015#012a=ice-pwd:x48BR8VoMg1rzHALOR8NIQVX2HkJ#015#012a=candidate:KerO0Gbge3TArmiM 1 UDP 2130706432 10.1.0.127 30004 typ host#015#012a=candidate:KerO0Gbge3TArmiM 2 UDP 2130706431 10.1.0.127 30005 typ host#015#0126:result2:oke
Aug 20 15:39:23 localhost /usr/local/sbin/kamailio[16455]: INFO: <script>: ERJ21 - 183 reply to INVITE to LYNCIT
Aug 20 15:39:23 localhost rtpengine[16797]: Got valid command from 127.0.0.1:52802: answer - { "sdp": "v=0#015#012o=- 0 0 IN IP4 192.168.2.106#015#012s=session#015#012c=IN IP4 192.168.2.106#015#012b=CT:100000#015#012t=0 0#015#012m=audio 33488 RTP/SAVP 8 97 96 13#015#012c=IN IP4 192.168.2.106#015#012a=rtcp:33489#015#012a=sendrecv#015#012a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:djhCCkKIpVs7FhDiWAvEYh96Fnk/XRzgbqjZDEW0|2^31|1:1#015#012a=rtpmap:8 PCMA/8000#015#012a=ptime:20#015#012a=label:main-audio#015#012a=x-ssrc-range:50-50#015#012a=x-source:main-audio#015#012a=rtcp-fb:* x-message app recv:dsh#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:96 telephone-event/8000#015#012a=fmtp:96 0-16#015#012a=rtpmap:13 CN/8000#015#012", "ICE": "remove", "transport-protocol": "RTP/AVP", "call-id": "NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA.", "received-from": [ "IP4", "192.168.2.106" ], "from-tag": "37030554", "to-tag": "8af01c2236", "command": "answer" }
Aug 20 15:39:23 localhost rtpengine[16797]: ERJ LOG_ERROR parse crypto 1 31
Aug 20 15:39:23 localhost rtpengine[16797]: ERJ LOG_INFO parse crypto 1 31
Aug 20 15:39:23 localhost rtpengine[16797]: ERJ parse crypto 2 2147483648
Aug 20 15:39:23 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA.] Returning to SIP proxy: d3:sdp399:v=0#015#012o=- 0 0 IN IP4 192.168.2.106#015#012s=session#015#012c=IN IP4 192.168.2.106#015#012b=CT:100000#015#012t=0 0#015#012m=audio 30006 RTP/AVP 8 97 96 13#015#012c=IN IP4 10.1.0.127#015#012a=rtpmap:8 PCMA/8000#015#012a=ptime:20#015#012a=label:main-audio#015#012a=x-ssrc-range:50-50#015#012a=x-source:main-audio#015#012a=rtcp-fb:* x-message app recv:dsh#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:96 telephone-event/8000#015#012a=fmtp:96 0-16#015#012a=rtpmap:13 CN/8000#015#012a=sendrecv#015#012a=rtcp:30007#015#0126:result2:oke
Aug 20 15:39:23 localhost /usr/local/sbin/kamailio[16455]: INFO: <script>: ERJ21 - 183 reply to INVITE to LYNCIT
Aug 20 15:39:23 localhost rtpengine[16797]: Got valid command from 127.0.0.1:52802: answer - { "sdp": "v=0#015#012o=- 0 0 IN IP4 192.168.2.106#015#012s=session#015#012c=IN IP4 192.168.2.106#015#012b=CT:100000#015#012t=0 0#015#012m=audio 33044 RTP/SAVP 8 97 96 13#015#012c=IN IP4 192.168.2.106#015#012a=rtcp:33045#015#012a=sendrecv#015#012a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:paTDb7m7aibIP3U6SDqPJBu+fjwTIo61Q4FAU6NO|2^31|1:1#015#012a=rtpmap:8 PCMA/8000#015#012a=ptime:20#015#012a=label:main-audio#015#012a=x-ssrc-range:49-49#015#012a=x-source:main-audio#015#012a=rtcp-fb:* x-message app recv:dsh#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:96 telephone-event/8000#015#012a=fmtp:96 0-16#015#012a=rtpmap:13 CN/8000#015#012", "ICE": "remove", "transport-protocol": "RTP/AVP", "call-id": "NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA.", "received-from": [ "IP4", "192.168.2.106" ], "from-tag": "37030554", "to-tag": "0b03fd664", "command": "answer" }
Aug 20 15:39:23 localhost rtpengine[16797]: ERJ LOG_ERROR parse crypto 1 31
Aug 20 15:39:23 localhost rtpengine[16797]: ERJ LOG_INFO parse crypto 1 31
Aug 20 15:39:23 localhost rtpengine[16797]: ERJ parse crypto 2 2147483648
Aug 20 15:39:23 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA.] Returning to SIP proxy: d3:sdp399:v=0#015#012o=- 0 0 IN IP4 192.168.2.106#015#012s=session#015#012c=IN IP4 192.168.2.106#015#012b=CT:100000#015#012t=0 0#015#012m=audio 30008 RTP/AVP 8 97 96 13#015#012c=IN IP4 10.1.0.127#015#012a=rtpmap:8 PCMA/8000#015#012a=ptime:20#015#012a=label:main-audio#015#012a=x-ssrc-range:49-49#015#012a=x-source:main-audio#015#012a=rtcp-fb:* x-message app recv:dsh#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:96 telephone-event/8000#015#012a=fmtp:96 0-16#015#012a=rtpmap:13 CN/8000#015#012a=sendrecv#015#012a=rtcp:30009#015#0126:result2:oke
Aug 20 15:39:23 localhost rtpengine[16797]: [87e8d333-7ecb-4ded-9aa6-59cd0aa7e4b4 port 30000] SRTP output wanted, but no crypto suite was negotiated
Aug 20 15:39:23 localhost rtpengine[16797]: [87e8d333-7ecb-4ded-9aa6-59cd0aa7e4b4 port 30001] SRTCP output wanted, but no crypto suite was negotiated
Aug 20 15:39:23 localhost rtpengine[16797]: [87e8d333-7ecb-4ded-9aa6-59cd0aa7e4b4 port 30000] SRTP output wanted, but no crypto suite was negotiated
Aug 20 15:39:23 localhost rtpengine[16797]: [87e8d333-7ecb-4ded-9aa6-59cd0aa7e4b4 port 30000] SRTP output wanted, but no crypto suite was negotiated
Aug 20 15:39:23 localhost rtpengine[16797]: [87e8d333-7ecb-4ded-9aa6-59cd0aa7e4b4 port 30000] SRTP output wanted, but no crypto suite was negotiated
Aug 20 15:39:23 localhost rtpengine[16797]: [87e8d333-7ecb-4ded-9aa6-59cd0aa7e4b4 port 30000] SRTP output wanted, but no crypto suite was negotiated
Aug 20 15:39:24 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:39:24 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:39:24 localhost rtpengine[16797]: [87e8d333-7ecb-4ded-9aa6-59cd0aa7e4b4 port 30000] SRTP output wanted, but no crypto suite was negotiated
Aug 20 15:39:24 localhost rtpengine[16797]: [87e8d333-7ecb-4ded-9aa6-59cd0aa7e4b4 port 30000] SRTP output wanted, but no crypto suite was negotiated
Aug 20 15:39:24 localhost rtpengine[16797]: [87e8d333-7ecb-4ded-9aa6-59cd0aa7e4b4 port 30000] SRTP output wanted, but no crypto suite was negotiated
Aug 20 15:39:24 localhost rtpengine[16797]: [87e8d333-7ecb-4ded-9aa6-59cd0aa7e4b4 port 30000] SRTP output wanted, but no crypto suite was negotiated
Aug 20 15:39:24 localhost rtpengine[16797]: [87e8d333-7ecb-4ded-9aa6-59cd0aa7e4b4 port 30000] SRTP output wanted, but no crypto suite was negotiated
Aug 20 15:39:24 localhost rtpengine[16797]: [87e8d333-7ecb-4ded-9aa6-59cd0aa7e4b4 port 30000] SRTP output wanted, but no crypto suite was negotiated
Aug 20 15:39:24 localhost rtpengine[16797]: [87e8d333-7ecb-4ded-9aa6-59cd0aa7e4b4 port 30000] SRTP output wanted, but no crypto suite was negotiated
Aug 20 15:39:24 localhost /usr/local/sbin/kamailio[16456]: INFO: <script>: ERJ20 - 183 reply to INVITE from LYNCIT
Aug 20 15:39:24 localhost rtpengine[16797]: Got valid command from 127.0.0.1:52063: answer - { "sdp": "v=0#015#012o=Redwood_INX 527637 527637 IN IP4 10.1.0.121#015#012s=Redwood Media Server#015#012c=IN IP4 10.1.0.121#015#012t=0 0#015#012m=audio 19610 RTP/AVP 8 97 101 13#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=rtpmap:13 CN/8000#015#012a=sendrecv#015#012", "ICE": "force", "flags": [ "force", "trust-address" ], "replace": [ "origin", "session-connection" ], "transport-protocol": "RTP/SAVP", "call-id": "87e8d333-7ecb-4ded-9aa6-59cd0aa7e4b4", "received-from": [ "IP4", "10.1.0.119" ], "from-tag": "914d1ecd9", "to-tag": "8c35cc21", "command": "answer" }
Aug 20 15:39:24 localhost rtpengine[16797]: [87e8d333-7ecb-4ded-9aa6-59cd0aa7e4b4] Returning to SIP proxy: d3:sdp587:v=0#015#012o=Redwood_INX 527637 527637 IN IP4 10.1.0.127#015#012s=Redwood Media Server#015#012c=IN IP4 10.1.0.127#015#012t=0 0#015#012a=ice-lite#015#012m=audio 30002 RTP/SAVP 8 97 101 13#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=rtpmap:13 CN/8000#015#012a=sendrecv#015#012a=rtcp:30003#015#012a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:a579+hYVJ5NSqCMQ3DKU8W6+F2xJBbEH5loYtrBd#015#012a=ice-ufrag:XRX950sU#015#012a=ice-pwd:TUC95BrH8pTpaUPHD38ijgfg7apc#015#012a=candidate:KerO0Gbge3TArmiM 1 UDP 2130706432 10.1.0.127 30002 typ host#015#012a=candidate:KerO0Gbge3TArmiM 2 UDP 2130706431 10.1.0.127 30003 typ host#015#0126:result2:oke
Aug 20 15:39:24 localhost /usr/local/sbin/kamailio[16456]: NOTICE: <script>: Enter main request route
Aug 20 15:39:24 localhost /usr/local/sbin/kamailio[16456]: INFO: <script>: Main request route PRACK
Aug 20 15:39:24 localhost /usr/local/sbin/kamailio[16456]: INFO: <script>: IN_DIALOG_TO_LYNCIT
Aug 20 15:39:24 localhost /usr/local/sbin/kamailio[16456]: INFO: <script>: ERJ08 - IN_DIALOG_TO_LYNCIT PRACK
Aug 20 15:39:24 localhost /usr/local/sbin/kamailio[16456]: INFO: <script>: ERJ10 - IN_DIALOG_TO_LYNCIT NO sdp
Aug 20 15:39:24 localhost /usr/local/sbin/kamailio[16455]: NOTICE: <script>: Enter main request route
Aug 20 15:39:24 localhost /usr/local/sbin/kamailio[16455]: INFO: <script>: Main request route PRACK
Aug 20 15:39:24 localhost /usr/local/sbin/kamailio[16455]: INFO: <script>: IN_DIALOG_FROM_LYNCIT
Aug 20 15:39:25 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:39:25 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:39:29 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:39:29 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:39:32 localhost /usr/local/sbin/kamailio[16456]: INFO: <script>: ERJ21 - 183 reply to INVITE to LYNCIT
Aug 20 15:39:32 localhost rtpengine[16797]: Got valid command from 127.0.0.1:52063: answer - { "sdp": "v=0#015#012o=- 0 0 IN IP4 192.168.2.106#015#012s=session#015#012c=IN IP4 192.168.2.106#015#012b=CT:100000#015#012t=0 0#015#012m=audio 33044 RTP/SAVP 8 97 96 13#015#012c=IN IP4 192.168.2.106#015#012a=rtcp:33045#015#012a=sendrecv#015#012a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:paTDb7m7aibIP3U6SDqPJBu+fjwTIo61Q4FAU6NO|2^31|1:1#015#012a=rtpmap:8 PCMA/8000#015#012a=ptime:20#015#012a=label:main-audio#015#012a=x-ssrc-range:49-49#015#012a=x-source:main-audio#015#012a=rtcp-fb:* x-message app recv:dsh#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:96 telephone-event/8000#015#012a=fmtp:96 0-16#015#012a=rtpmap:13 CN/8000#015#012", "ICE": "remove", "transport-protocol": "RTP/AVP", "call-id": "NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA.", "received-from": [ "IP4", "192.168.2.106" ], "from-tag": "37030554", "to-tag": "0b03fd664", "command": "answer" }
Aug 20 15:39:32 localhost rtpengine[16797]: ERJ LOG_ERROR parse crypto 1 31
Aug 20 15:39:32 localhost rtpengine[16797]: ERJ LOG_INFO parse crypto 1 31
Aug 20 15:39:32 localhost rtpengine[16797]: ERJ parse crypto 2 2147483648
Aug 20 15:39:32 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA.] Returning to SIP proxy: d3:sdp399:v=0#015#012o=- 0 0 IN IP4 192.168.2.106#015#012s=session#015#012c=IN IP4 192.168.2.106#015#012b=CT:100000#015#012t=0 0#015#012m=audio 30008 RTP/AVP 8 97 96 13#015#012c=IN IP4 10.1.0.127#015#012a=rtpmap:8 PCMA/8000#015#012a=ptime:20#015#012a=label:main-audio#015#012a=x-ssrc-range:49-49#015#012a=x-source:main-audio#015#012a=rtcp-fb:* x-message app recv:dsh#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:96 telephone-event/8000#015#012a=fmtp:96 0-16#015#012a=rtpmap:13 CN/8000#015#012a=sendrecv#015#012a=rtcp:30009#015#0126:result2:oke
Aug 20 15:39:32 localhost /usr/local/sbin/kamailio[16455]: INFO: <script>: ERJ20 - 183 reply to INVITE from LYNCIT
Aug 20 15:39:32 localhost rtpengine[16797]: Got valid command from 127.0.0.1:52802: answer - { "sdp": "v=0#015#012o=Redwood_INX 527637 527637 IN IP4 10.1.0.121#015#012s=Redwood Media Server#015#012c=IN IP4 10.1.0.121#015#012t=0 0#015#012m=audio 19610 RTP/AVP 8 97 101 13#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=rtpmap:13 CN/8000#015#012a=sendrecv#015#012", "ICE": "force", "flags": [ "force", "trust-address" ], "replace": [ "origin", "session-connection" ], "transport-protocol": "RTP/SAVP", "call-id": "87e8d333-7ecb-4ded-9aa6-59cd0aa7e4b4", "received-from": [ "IP4", "10.1.0.119" ], "from-tag": "914d1ecd9", "to-tag": "8c35cc21", "command": "answer" }
Aug 20 15:39:32 localhost rtpengine[16797]: [87e8d333-7ecb-4ded-9aa6-59cd0aa7e4b4] Returning to SIP proxy: d3:sdp587:v=0#015#012o=Redwood_INX 527637 527637 IN IP4 10.1.0.127#015#012s=Redwood Media Server#015#012c=IN IP4 10.1.0.127#015#012t=0 0#015#012a=ice-lite#015#012m=audio 30002 RTP/SAVP 8 97 101 13#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=rtpmap:13 CN/8000#015#012a=sendrecv#015#012a=rtcp:30003#015#012a=crypto:4 AES_CM_128_HMAC_SHA1_80 inline:a579+hYVJ5NSqCMQ3DKU8W6+F2xJBbEH5loYtrBd#015#012a=ice-ufrag:XRX950sU#015#012a=ice-pwd:TUC95BrH8pTpaUPHD38ijgfg7apc#015#012a=candidate:KerO0Gbge3TArmiM 1 UDP 2130706432 10.1.0.127 30002 typ host#015#012a=candidate:KerO0Gbge3TArmiM 2 UDP 2130706431 10.1.0.127 30003 typ host#015#0126:result2:oke
Aug 20 15:39:32 localhost /usr/local/sbin/kamailio[16455]: NOTICE: <script>: Enter main request route
Aug 20 15:39:32 localhost /usr/local/sbin/kamailio[16455]: INFO: <script>: Main request route ACK
Aug 20 15:39:32 localhost /usr/local/sbin/kamailio[16455]: INFO: <script>: IN_DIALOG_TO_LYNCIT
Aug 20 15:39:32 localhost /usr/local/sbin/kamailio[16455]: INFO: <script>: ERJ10 - IN_DIALOG_TO_LYNCIT NO sdp
Aug 20 15:39:32 localhost /usr/local/sbin/kamailio[16456]: NOTICE: <script>: Enter main request route
Aug 20 15:39:32 localhost /usr/local/sbin/kamailio[16456]: INFO: <script>: Main request route ACK
Aug 20 15:39:32 localhost /usr/local/sbin/kamailio[16456]: INFO: <script>: IN_DIALOG_FROM_LYNCIT
Aug 20 15:39:34 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:39:34 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:39:38 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:39:38 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:39:41 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:39:41 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:39:42 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30004] Error parsing RTP header: invalid header version
Aug 20 15:39:45 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:39:45 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:39:48 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:39:48 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:39:51 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:39:51 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:39:56 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:39:56 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:40:01 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:40:01 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:40:01 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30004] Error parsing RTP header: invalid header version
Aug 20 15:40:05 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:40:05 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:40:09 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:40:09 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:40:11 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:40:11 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:40:15 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:40:15 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:40:19 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:40:19 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:40:20 localhost /usr/local/sbin/kamailio[16455]: NOTICE: <script>: Enter main request route
Aug 20 15:40:20 localhost /usr/local/sbin/kamailio[16455]: INFO: <script>: Main request route OPTIONS
Aug 20 15:40:20 localhost /usr/local/sbin/kamailio[16456]: NOTICE: <script>: Enter main request route
Aug 20 15:40:20 localhost /usr/local/sbin/kamailio[16456]: INFO: <script>: Main request route OPTIONS
Aug 20 15:40:20 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30004] Error parsing RTP header: invalid header version
Aug 20 15:40:25 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:40:25 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:40:26 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30004] Error parsing RTP header: invalid header version
Aug 20 15:40:28 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:40:28 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:40:31 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:40:31 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:40:33 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:40:33 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:40:37 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:40:37 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:40:39 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30004] Error parsing RTP header: invalid header version
Aug 20 15:40:40 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:40:40 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:40:45 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30004] Error parsing RTP header: invalid header version
Aug 20 15:40:46 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:40:46 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:40:50 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:40:50 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:40:54 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:40:54 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:40:58 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30004] Error parsing RTP header: invalid header version
Aug 20 15:41:00 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:41:00 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:41:02 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:41:02 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:41:04 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30004] Error parsing RTP header: invalid header version
Aug 20 15:41:07 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:41:07 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:41:10 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:41:10 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:41:14 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:41:14 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:41:17 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30004] Error parsing RTP header: invalid header version
Aug 20 15:41:19 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:41:19 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:41:20 localhost /usr/local/sbin/kamailio[16456]: NOTICE: <script>: Enter main request route
Aug 20 15:41:20 localhost /usr/local/sbin/kamailio[16456]: INFO: <script>: Main request route OPTIONS
Aug 20 15:41:20 localhost /usr/local/sbin/kamailio[16455]: NOTICE: <script>: Enter main request route
Aug 20 15:41:20 localhost /usr/local/sbin/kamailio[16455]: INFO: <script>: Main request route OPTIONS
Aug 20 15:41:23 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:41:23 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:41:23 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30004] Error parsing RTP header: invalid header version
Aug 20 15:41:27 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:41:27 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:41:32 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:41:32 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:41:36 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30004] Error parsing RTP header: invalid header version
Aug 20 15:41:38 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:41:38 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:41:42 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30004] Error parsing RTP header: invalid header version
Aug 20 15:41:43 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:41:43 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:41:46 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:41:46 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:41:50 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:41:50 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:41:54 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:41:54 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:41:56 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30004] Error parsing RTP header: invalid header version
Aug 20 15:41:56 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:41:56 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:42:00 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:42:00 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:42:01 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30004] Error parsing RTP header: invalid header version
Aug 20 15:42:03 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:42:03 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:42:07 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:42:07 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:42:11 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:42:11 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:42:15 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30004] Error parsing RTP header: invalid header version
Aug 20 15:42:15 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:42:15 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:42:20 localhost /usr/local/sbin/kamailio[16456]: NOTICE: <script>: Enter main request route
Aug 20 15:42:20 localhost /usr/local/sbin/kamailio[16456]: INFO: <script>: Main request route OPTIONS
Aug 20 15:42:20 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30004] Error parsing RTP header: invalid header version
Aug 20 15:42:20 localhost /usr/local/sbin/kamailio[16455]: NOTICE: <script>: Enter main request route
Aug 20 15:42:20 localhost /usr/local/sbin/kamailio[16455]: INFO: <script>: Main request route OPTIONS
Aug 20 15:42:21 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:42:21 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:42:27 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:42:27 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:42:32 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:42:32 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:42:34 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30004] Error parsing RTP header: invalid header version
Aug 20 15:42:35 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:42:35 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:42:39 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30004] Error parsing RTP header: invalid header version
Aug 20 15:42:40 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:42:40 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:42:46 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:42:46 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:42:48 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:42:48 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:42:53 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30004] Error parsing RTP header: invalid header version
Aug 20 15:42:53 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:42:53 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:42:57 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:42:57 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:42:58 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30004] Error parsing RTP header: invalid header version
Aug 20 15:43:01 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:43:01 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:43:04 localhost /usr/local/sbin/kamailio[16456]: NOTICE: <script>: Enter main request route
Aug 20 15:43:04 localhost /usr/local/sbin/kamailio[16456]: INFO: <script>: Main request route BYE
Aug 20 15:43:04 localhost /usr/local/sbin/kamailio[16456]: INFO: <script>: IN_DIALOG_FROM_LYNCIT
Aug 20 15:43:05 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA. port 30005] Discarded invalid SRTCP packet: authentication failed
Aug 20 15:43:05 localhost /usr/local/sbin/kamailio[16456]: NOTICE: <script>: Enter main request route
Aug 20 15:43:05 localhost /usr/local/sbin/kamailio[16456]: INFO: <script>: Main request route BYE
Aug 20 15:43:05 localhost /usr/local/sbin/kamailio[16456]: INFO: <script>: IN_DIALOG_TO_LYNCIT
Aug 20 15:43:05 localhost /usr/local/sbin/kamailio[16456]: INFO: <script>: ERJ10 - IN_DIALOG_TO_LYNCIT NO sdp
Aug 20 15:43:20 localhost /usr/local/sbin/kamailio[16455]: NOTICE: <script>: Enter main request route
Aug 20 15:43:20 localhost /usr/local/sbin/kamailio[16455]: INFO: <script>: Main request route OPTIONS
Aug 20 15:43:20 localhost /usr/local/sbin/kamailio[16456]: NOTICE: <script>: Enter main request route
Aug 20 15:43:20 localhost /usr/local/sbin/kamailio[16456]: INFO: <script>: Main request route OPTIONS
Aug 20 15:44:04 localhost rtpengine[16797]: Closing call branch due to timeout
Aug 20 15:44:04 localhost rtpengine[16797]: [87e8d333-7ecb-4ded-9aa6-59cd0aa7e4b4] Final packet stats:
Aug 20 15:44:04 localhost rtpengine[16797]: [87e8d333-7ecb-4ded-9aa6-59cd0aa7e4b4] --- Tag '8c35cc21', created 4:42 ago, in dialogue with '914d1ecd9'
Aug 20 15:44:04 localhost rtpengine[16797]: [87e8d333-7ecb-4ded-9aa6-59cd0aa7e4b4] ------ Media #1, port 30002 <> 192.168.2.106:33042, 10561 p, 1816333 b, 0 e
Aug 20 15:44:04 localhost rtpengine[16797]: [87e8d333-7ecb-4ded-9aa6-59cd0aa7e4b4] ------ Media #1, port 30003 <> 192.168.2.106:33043 (RTCP), 143 p, 8772 b, 0 e
Aug 20 15:44:04 localhost rtpengine[16797]: [87e8d333-7ecb-4ded-9aa6-59cd0aa7e4b4] --- Tag '914d1ecd9', created 4:42 ago, in dialogue with '8c35cc21'
Aug 20 15:44:04 localhost rtpengine[16797]: [87e8d333-7ecb-4ded-9aa6-59cd0aa7e4b4] ------ Media #1, port 30000 <> 10.1.0.121:19610, 93 p, 15852 b, 0 e
Aug 20 15:44:04 localhost rtpengine[16797]: [87e8d333-7ecb-4ded-9aa6-59cd0aa7e4b4] ------ Media #1, port 30001 <> 10.1.0.121:19611 (RTCP), 28 p, 1938 b, 0 e
Aug 20 15:44:05 localhost rtpengine[16797]: Closing call branch due to timeout
Aug 20 15:44:05 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA.] Final packet stats:
Aug 20 15:44:05 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA.] --- Tag '0b03fd664', created 4:42 ago, in dialogue with '37030554'
Aug 20 15:44:05 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA.] ------ Media #1, port 30008 <> [::]:0 , 10621 p, 1931591 b, 0 e
Aug 20 15:44:05 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA.] ------ Media #1, port 30009 <> [::]:0 (RTCP), 29 p, 1914 b, 0 e
Aug 20 15:44:05 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA.] --- Tag '8af01c2236', created 4:42 ago, in dialogue with '37030554'
Aug 20 15:44:05 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA.] ------ Media #1, port 30006 <> 10.1.0.121:19620, 0 p, 0 b, 0 e
Aug 20 15:44:05 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA.] ------ Media #1, port 30007 <> 10.1.0.121:19621 (RTCP), 0 p, 0 b, 0 e
Aug 20 15:44:05 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA.] --- Tag '37030554', created 4:42 ago, in dialogue with '0b03fd664'
Aug 20 15:44:05 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA.] ------ Media #1, port 30004 <> 192.168.2.106:33044, 2129 p, 363310 b, 0 e
Aug 20 15:44:05 localhost rtpengine[16797]: [NjdlZDk2OThmY2E1M2QxN2RkYWUwMWIzNmExOWQ3MjA.] ------ Media #1, port 30005 <> 192.168.2.106:33045 (RTCP), 226 p, 15837 b, 0 e

from rtpengine.

rfuchs commented on June 24, 2024

The message "SRTP output wanted, but no crypto suite was negotiated" in this call is actually expected. It occurs when early media is received from the RTP endpoint before the SDP answer has been sent to the SRTP endpoint. SRTP can only be sent after the SDP answer has been processed, so any RTP received before that must be discarded with this message.

I'm more concerned about the "authentication failed" messages, those shouldn't be there. There might be a problem with how the MKI is handled, I haven't done any testing with the MKI due to the lack of a client using the MKI. Perhaps you could create a complete tcpdump including the RTP and SRTP packets for one such call, so I can see why the authantication fails for these packets. The fact that rtpengine doesn't use an MKI itself shouldn't be a problem.

from rtpengine.

edjames99 commented on June 24, 2024

Hi Richard,
I've put links at the bottom of this message for the file LyncIT_RTPEngineTrace.pcap which can be opened in Wireshark. I've also added a link to the private key Kam_KeyOnly.pem so that Wireshark can decrypt the SSL packets.

In Wireshark go to Edit->Preferences->Protocols->SSL then Edit->New then:

IP Address: 10.1.0.127 (this is the Kamailio IP)
Port: 5061
Protocol: sip
Key File: \Kam_KeyOnly.pem
This should enable you to see the SRTP packets.

Also if you put this filter into Wireshark it will help (192.168.2.106 is Lync Client IP and 10.1.0.121 is our platform media card IP)

udp && ((ip.src==192.168.2.106) || (ip.dst==192.168.2.106) || (ip.src==10.1.0.121) || (ip.dst==10.1.0.121))

Let me know if you need more traces etc..

Thanks for your help - it's much appreciated.
Ed

http://www.thephoneangel.com/LyncIT_RTPEngineTrace.pcap
http://www.thephoneangel.com/Kam_KeyOnly.pem

from rtpengine.

rfuchs commented on June 24, 2024

Thanks, could you also please post the rtpengine log from this particular call

from rtpengine.

edjames99 commented on June 24, 2024

Hi Richard,
Apologies for the delay, but I've uploaded the packet capture and kamailio log for a new test call. The call with id da6dcca5-a21b-4ed6-aaab-3e79f7d875aa works fine and the call with id MjkxMWU2MTdmOTNiZDM1NGU0OGQxYjEzMGQ4ZjhkYTA. is the one which is failing.

Thanks
Ed
http://www.thephoneangel.com/LyncIT_RTPEngineTrace_20140826.pcap
http://www.thephoneangel.com/Kam_KeyOnly.pem
http://www.thephoneangel.com/KamailioLog_20140826

from rtpengine.

rfuchs commented on June 24, 2024

Ok, so in the log file, I see two calls, da6dcca5-a21b-4ed6-aaab-3e79f7d875aa and MjkxMWU2MTdmOTNiZDM1NGU0OGQxYjEzMGQ4ZjhkYTA. However in the pcap, I only see one call (the first one), but it looks like the problematic one is the second one. Is there a second port in the pcap which also carries encrypted SIP?

from rtpengine.

edjames99 commented on June 24, 2024

Call da6dcca5-a21b-4ed6-aaab-3e79f7d875aa (encrypted INVITE inbound into RTPEngine) has RTP between:

10.1.0.127:30142 (RTP Engine) and 192.168.2.106:33042 (MS Lync)

In wireshark if you filter 'udp.srcport == 33042' or filter 'udp.srcport == 30142' then you see all SRTP packets - so that's OK.

Call MjkxMWU2MTdmOTNiZDM1NGU0OGQxYjEzMGQ4ZjhkYTA. (encrypted INVITE outbound from RTPEngine) has media between:

10.1.0.127:30144 (RTP Engine) and 192.168.2.106:33044 (MS Lync)

In Wireshark if you filter 'udp.srcport == 30144' or filter 'udp.srcport == 33044' then you see all UDP packets where you'd expect SRTP packets.

I'm assuming that the MjkxMWU2MTdmOTNiZDM1NGU0OGQxYjEzMGQ4ZjhkYTA. call is not showing SRTP because the initial SDP negotiation failed somehow but the SIP messages look OK to me, the only difference I can see is that the RTP Engine doesn't offer |2^31|1:1 in the crypto attribute in an outbound INVITE and doesn't answer |2^31|1:1 in the crypto attribute in a 183 to an inbound INVITE but the issue might not be down to this difference.

I can send you the complete SIP message history and also my Kamailio config file if that would be of use - it could be something to do with the way I'm calling the rtpproxy_manage function but the SIP exchange does look OK to me.

Thanks for your help.

from rtpengine.

rfuchs commented on June 24, 2024

I think I see the problem.

In the second call (MjkxMW...), the A side first sends an offer (RTP from port 19080, translated to SRTP port 30144), then the B side sends an answer (SRTP from port 33488, translated to 30146). All is fine so far.

Then the B side sends another answer, with a different port (33044) and different SRTP parameters (different key). The port change is no problem (rtpengine translates it to 30148), but the key change doesn't work. This results in failed authentication, discarded packets and no audio. I should have a fix for that shortly.

The other log message ("Error parsing RTP header: invalid header version") is actually exactly what it says. In your most recent dump for example, packet 26305 is supposed to contain RTP but seems to contain some other garbage. Not sure what those are, perhaps they'll go away after the key change problem is fixed.

from rtpengine.

rfuchs commented on June 24, 2024

Actually I have to take that back, key change does seem to be working, it was my test script that was broken. Back to looking...

from rtpengine.

rfuchs commented on June 24, 2024

On further investigation, it looks like the key change isn't actually a key change, but rather two endpoints (two registrations?) answering the call at the same time.

The first answer was advertising encrypted RTP on port 33488 (RTCP on 33489). The second answer (different to-tag, so a different registration/endpoint?) came less than a second later and was advertising encrypted RTP on port 33044 (RTCP on 33045) with a different encryption key. The second answer overrides the first one.

I've looked at an RTCP packet from your pcap, packet 2850. It comes from port 33489, so it was probably the first endpoint sending it, and indeed the authentication tag matches if you use the encryption key from the first answer. However, rtpengine expects to be talking to the second endpoint and so it wants to use the encryption key from the second answer. Authentication fails, error is logged, packet is dropped.

At the same time, RTP packets come in from port 33044, which is the first endpoint (packet 2953) and are encrypted using the key from the second answer. Those should get processed correctly, but the A-side (10.1.0.121, local port 30146 or 30148) is missing from the pcap, so I can't tell what's going on there.

I understand that Lync supports conferencing services, is that what's happening here?

from rtpengine.

edjames99 commented on June 24, 2024

OK that all makes sense, if I compare the packets sent from 33488/9 (KEY1) and 33044/5 (KEY2) and received on 30144/5 they do correlate with the error messages in the log:

KEY1:
33488 CLASSIC-STUN 11 packets
33489 SRTCP 113 packets

KEY2:
33044 SRTP + CLASSIC-STUN 9 packets
33045 SRTCP

The 'Discarded invalid SRTCP packet' error occurs 113 times and the 'Error parsing RTP header' error occurs 20 times (for the total number of CLASSIC_STUN packets) so that all makes sense.

Looking at the final packet stats it looks like the engine still links the 30146/7 pair of translated ports to 10.1.0.121:19080/1 and it doesn't link 30148/9 translated ports to 10.1.0.121:19080/1. So maybe the engine has overwritten the key to use the key from the second answer but it hasn't updated the translated ports from the second answer to be mapped to 10.1.0.121:19080/1. Does the '[::]:0' entry indicate this in the log extract below ?

Aug 26 10:35:05 localhost rtpengine[16797]: [MjkxMWU2MTdmOTNiZDM1NGU0OGQxYjEzMGQ4ZjhkYTA.] Final packet stats:

Aug 26 10:35:05 localhost rtpengine[16797]: [MjkxMWU2MTdmOTNiZDM1NGU0OGQxYjEzMGQ4ZjhkYTA.] --- Tag '50ad6ca53', created 4:42 ago, in dialogue with 'd27bb023'

Aug 26 10:35:05 localhost rtpengine[16797]: [MjkxMWU2MTdmOTNiZDM1NGU0OGQxYjEzMGQ4ZjhkYTA.] ------ Media #1, port 30148 <> [::]:0 , 10645 p, 1935959 b, 0 e

Aug 26 10:35:05 localhost rtpengine[16797]: [MjkxMWU2MTdmOTNiZDM1NGU0OGQxYjEzMGQ4ZjhkYTA.] ------ Media #1, port 30149 <> [::]:0 (RTCP), 28 p, 1848 b, 0 e

Aug 26 10:35:05 localhost rtpengine[16797]: [MjkxMWU2MTdmOTNiZDM1NGU0OGQxYjEzMGQ4ZjhkYTA.] --- Tag '156b2a6f9c', created 4:42 ago, in dialogue with 'd27bb023'

Aug 26 10:35:05 localhost rtpengine[16797]: [MjkxMWU2MTdmOTNiZDM1NGU0OGQxYjEzMGQ4ZjhkYTA.] ------ Media #1, port 30146 <> 10.1.0.121:19080, 0 p, 0 b, 0 e

Aug 26 10:35:05 localhost rtpengine[16797]: [MjkxMWU2MTdmOTNiZDM1NGU0OGQxYjEzMGQ4ZjhkYTA.] ------ Media #1, port 30147 <> 10.1.0.121:19081 (RTCP), 0 p, 0 b, 0 e

If I do a Wireshark of 'udp.dstport == 19080' there are no packets being sent to this port on 10.1.0.121 but there are SRTP (from 33044) and SRTCP (from 33045) packets coming into 30144/5 successfully. Also as you say I think the packets from 33044/5 (KEY2) must be being decrypted by the RTPEngine otherwise we'd have error messages relating to this as well and we don't.

The client we are using isn't Lync itself it's a Lync testing tool called LyncIT which we have to use to become Lync certified. It's a black box client which we have no control over. It is a single LyncIT end point which is sending both 183 answers containing different To tags, I'm sure why they're different (maybe it's mimicking forking behind the single end point) or if they have to be the same in the RFC but certainly all of the SIP messages after the second 183 contain the To tag from that second 183 so the RTPEngine dropping the first key looks correct to me. I'm not sure why LyncIT would send packets encrypted with the first key after having sent a second key, it might not matter as far as the test goes if the KEY2 packets reach the other end.

Thanks for your help, if you need a pcap with 10.1.0.121 included please let me know.

from rtpengine.

rfuchs commented on June 24, 2024

Yes, these kinds of 3-was associations aren't well supported yet. I'll try to sort it out, but I'm not sure if that will fix your problem, as I'm still not totally sure what the expected behaviour is.

from rtpengine.

rfuchs commented on June 24, 2024

So with the following patch applied:

16b42fb

replaying the signalling gives you the following associations:

Aug 28 15:44:57 tabasco rtpengine[2555]: [asdgahahadfghadf] Closing call due to timeout
Aug 28 15:44:57 tabasco rtpengine[2555]: [asdgahahadfghadf] Final packet stats:
Aug 28 15:44:57 tabasco rtpengine[2555]: [asdgahahadfghadf] --- Tag '50ad6ca53', created 1:00 ago, in dialogue with 'd27bb023'
Aug 28 15:44:57 tabasco rtpengine[2555]: [asdgahahadfghadf] ------ Media #1, port 30006 <>   192.168.2.106:33044, 0 p, 0 b, 0 e
Aug 28 15:44:57 tabasco rtpengine[2555]: [asdgahahadfghadf] ------ Media #1, port 30007 <>   192.168.2.106:33045 (RTCP), 0 p, 0 b, 0 e
Aug 28 15:44:57 tabasco rtpengine[2555]: [asdgahahadfghadf] --- Tag '156b2a6f9c', created 1:07 ago, in dialogue with 'd27bb023'
Aug 28 15:44:57 tabasco rtpengine[2555]: [asdgahahadfghadf] ------ Media #1, port 30000 <>   192.168.2.106:33488, 0 p, 0 b, 0 e
Aug 28 15:44:57 tabasco rtpengine[2555]: [asdgahahadfghadf] ------ Media #1, port 30001 <>   192.168.2.106:33489 (RTCP), 0 p, 0 b, 0 e
Aug 28 15:44:57 tabasco rtpengine[2555]: [asdgahahadfghadf] --- Tag 'd27bb023', created 1:07 ago, in dialogue with '50ad6ca53'
Aug 28 15:44:57 tabasco rtpengine[2555]: [asdgahahadfghadf] ------ Media #1, port 30004 <>      10.1.0.121:19080, 0 p, 0 b, 0 e
Aug 28 15:44:57 tabasco rtpengine[2555]: [asdgahahadfghadf] ------ Media #1, port 30005 <>      10.1.0.121:19081 (RTCP), 0 p, 0 b, 0 e

which looks much more healthier. I still can't say if that really fixes your setup though, but it should be a step in the right direction.

from rtpengine.

edjames99 commented on June 24, 2024

Hi Richard,
Thanks for the changes, I've built the latest source locally and rebooted the Kamailio (so there is no /proc/mediaproxy/ folder) and when I run the start up sequence I get:

FAILED TO OPEN KERNEL TABLE 0, KERNEL FORWARDING DISABLED

The start up sequence I'm using is the following:

service mysqld start
service kamailio start --for rtpproxy
modprobe xt_MEDIAPROXY
iptables -I INPUT -p udp -d 10.1.0.127 -j MEDIAPROXY --id 0
echo 'del 0' > /proc/mediaproxy/control
/usr/bin/rtpengine --table=0 --ip=10.1.0.127 --listen-ng=127.0.0.1:2223 --tos=184 --pidfile=/var/run/rtpengine.pid --log-level=7 --no-fallback
service mysqld start
service kamailio start

I realise this is a pilot error issue but any help would be appreciated.

Thanks

from rtpengine.

rfuchs commented on June 24, 2024

/proc/mediaproxy/ should appear after you run the modprobe command. You can check the output of lsmod to see if it's loaded. Note that modprobe searches for the module in /lib/modules/, so if you've just compiled it somewhere and didn't install it into the system, modprobe won't find it. Use insmod to load the module for a different place manually.

from rtpengine.

edjames99 commented on June 24, 2024

Just a FYI - my previous build still works with the same start up sequence.
Thanks

from rtpengine.

rfuchs commented on June 24, 2024

Nothing has changed in the kernel interface for a long time, so it shouldn't make a difference.

from rtpengine.

edjames99 commented on June 24, 2024

When you say it 'searches for the module' what file is it actually looking for ? All I've done is copy the new source onto the machine and run the Makefile in the kernel-module, iptables-extension and daemon folder. Do I need to copy something into /lib/modules ?

Sorry I'm not familiar with Linux - thanks for your help.

from rtpengine.

rfuchs commented on June 24, 2024

The compiled module file is called xt_MEDIAPROXY.ko, you should find it in the kernel-module directory if you've compiled it there. You can load the module from that file directly with insmod xt_MEDIAPROXY.ko

Alternatively you can copy it (or make a symlink) into /lib/modules/, find the subdirectory matching your kernel's version (as printed by uname -r) and put it into a suitable directory. Best suited is updates if you have that, otherwise somewhere in kernel, such as kernel/net/netfilter. Afterwards run depmod -a to update the module dependencies.

The compiled iptables module also needs to go into /lib/xtables/ for iptables to find it.

from rtpengine.

edjames99 commented on June 24, 2024

When I run that start sequence which gives the error and then I run lsmod it does show xt_MEDIAPROXY with a Used By of 2 so I think the module has been loaded and also the mediaproxy folder does exist and contains a zero folder.

from rtpengine.

rfuchs commented on June 24, 2024

In that case all you need to do is delete the zero table (using the del 0 command) and start rtpengine.

from rtpengine.

edjames99 commented on June 24, 2024

OK thanks for the details - so at the moment I must be loading the previous builds of these modules with the new RTPEngine.

from rtpengine.

rfuchs commented on June 24, 2024

The kernel module hasn't actually changed, so it shouldn't make a difference which build of the module you're loading.

from rtpengine.

edjames99 commented on June 24, 2024

Sorry to keep asking you basic questions but which folder should I be in when I run depmod -a and also what file is the compiled iptables module (running the make file created libxt_MEDIAPROXY.so - is that it given it's not a .ko file ?) Also I don't have a /lib/xtables folder and presumably the previous build of the ip tables module is already on my machine somewhere.

Thanks again.

from rtpengine.

rfuchs commented on June 24, 2024

Yeah that's the one. .ko is kernel module, .so is user-space module. If you can run the iptables command from your startup sequence without error, then the module is already installed correctly somewhere. Perhaps you're using an older version of iptables (pre-xtables), I believe it had its modules in /lib/iptables/

from rtpengine.

edjames99 commented on June 24, 2024

I've updated the iptables module (it was in lib64/xtables) and also the kernel module (and then ran depmod -a) and now the RTPEngine runs (just updating iptables didn't remove the error). However when I try and put calls through it I get a lot of errors and no modification of the sdp. The errors are these below repeated many times:

Aug 29 17:35:35 localhost /usr/local/sbin/kamailio[2500]: ERROR: rtpproxy-ng [rtpproxy.c:1513]: send_rtpp_command(): can't send command to a RTP proxy
Aug 29 17:35:35 localhost /usr/local/sbin/kamailio[2500]: ERROR: rtpproxy-ng [rtpproxy.c:1549]: send_rtpp_command(): proxy udp:127.0.0.1:2223 does not respond, disable it
Aug 29 17:35:35 localhost /usr/local/sbin/kamailio[2500]: ERROR: rtpproxy-ng [rtpproxy.c:1419]: rtpp_test(): proxy did not respond to ping

I can send you the whole log file if you need it - Thanks.

from rtpengine.

rfuchs commented on June 24, 2024

Any chance that you've changed the startup command line parameters, or that you're having iptables issues again? The messages sent by kamailio don't seem to be getting through to the rtpengine daemon.

from rtpengine.

edjames99 commented on June 24, 2024

I cleared out iptables before running the startup sequence (which correctly added the INPUT rule for MEDIAPROXY) and am running the same start sequence as before. Here's some more of the log file:

Aug 29 18:10:08 localhost vmusr[2168]: [ warning] [Gtk] Unable to locate theme engine in module_path: "clearlooks",
Aug 29 18:10:08 localhost vmusr[2168]: [ warning] [Gtk] Unable to locate theme engine in module_path: "clearlooks",
Aug 29 18:10:08 localhost vmusr[2168]: [ warning] [Gtk] Unable to locate theme engine in module_path: "clearlooks",
Aug 29 18:10:08 localhost vmusr[2168]: [ warning] [Gtk] Unable to locate theme engine in module_path: "clearlooks",
Aug 29 18:10:08 localhost vmusr[2168]: [ warning] [Gtk] Unable to locate theme engine in module_path: "clearlooks",
Aug 29 18:10:08 localhost vmusr[2168]: [ warning] [Gtk] Unable to locate theme engine in module_path: "clearlooks",
Aug 29 18:10:08 localhost vmusr[2168]: [ warning] [Gtk] Unable to locate theme engine in module_path: "clearlooks",
Aug 29 18:10:08 localhost vmusr[2168]: [ warning] [Gtk] Unable to locate theme engine in module_path: "clearlooks",
Aug 29 18:10:08 localhost vmusr[2168]: [ warning] [Gtk] Unable to locate theme engine in module_path: "clearlooks",
Aug 29 18:10:08 localhost vmusr[2168]: [ warning] [Gtk] Unable to locate theme engine in module_path: "clearlooks",
Aug 29 18:10:08 localhost vmusr[2168]: [ warning] [Gtk] Unable to locate theme engine in module_path: "clearlooks",
Aug 29 18:10:08 localhost vmusr[2168]: [ warning] [Gtk] Unable to locate theme engine in module_path: "clearlooks",
Aug 29 18:10:08 localhost vmusr[2168]: [ warning] [Gtk] Unable to locate theme engine in module_path: "clearlooks",
Aug 29 18:10:08 localhost vmusr[2168]: [ warning] [Gtk] Unable to locate theme engine in module_path: "clearlooks",
Aug 29 18:10:08 localhost vmusr[2168]: [ warning] [Gtk] gtk_disable_setlocale() must be called before gtk_init()
Aug 29 18:12:02 localhost kamailio: INFO: tls [tls_init.c:385]: init_tls_compression(): tls: init_tls: disabling compression...
Aug 29 18:12:02 localhost kamailio: INFO: [tcp_main.c:4836]: init_tcp(): init_tcp: using epoll_lt as the io watch method (auto detected)
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: INFO: rr [../outbound/api.h:54]: ob_load_api(): Failed to import bind_ob
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: INFO: rr [rr_mod.c:159]: mod_init(): outbound module not available
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: INFO: path [../outbound/api.h:54]: ob_load_api(): Failed to import bind_ob
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: INFO: path [path_mod.c:147]: mod_init(): outbound module not available
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: INFO: tls [tls_init.c:549]: init_tls_h(): tls: _init_tls_h: compiled with openssl version "OpenSSL 1.0.1e-fips 11 Feb 2013" (0x1000105f), kerberos support: on, compression: on
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: INFO: tls [tls_init.c:557]: init_tls_h(): tls: init_tls_h: installed openssl library version "OpenSSL 1.0.1e-fips 11 Feb 2013" (0x1000105f), kerberos support: on, zlib compression: on#012 compiler: gcc -fPIC -DOPENSSL_PIC -DZLIB -DOPENSSL_THREADS -D_REENTRANT -DDSO_DLFCN -DHAVE_DLFCN_H -DKRB5_MIT -m64 -DL_ENDIAN -DTERMIO -Wall -O2 -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector --param=ssp-buffer-size=4 -m64 -mtune=generic -Wa,--noexecstack -DPURIFY -DOPENSSL_IA32_SSE2 -DOPENSSL_BN_ASM_MONT -DOPENSSL_BN_ASM_MONT5 -DOPENSSL_BN_ASM_GF2m -DSHA1_ASM -DSHA256_ASM -DSHA512_ASM -DMD5_ASM -DAES_ASM -DVPAES_ASM -DBSAES_ASM -DWHIRLPOOL_ASM -DGHASH_ASM
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: WARNING: tls [tls_init.c:611]: init_tls_h(): tls: openssl bug #1491 (crash/mem leaks on low memory) workaround enabled (on low memory tls operations will fail preemptively) with free memory thresholds 4194304 and 2097152 bytes
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: INFO: [cfg/cfg_ctx.c:613]: cfg_set_now(): INFO: cfg_set_now(): tls.low_mem_threshold1 has been changed to 4194304
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: INFO: [cfg/cfg_ctx.c:613]: cfg_set_now(): INFO: cfg_set_now(): tls.low_mem_threshold2 has been changed to 2097152
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: ERROR: rtpproxy-ng [rtpproxy.c:1513]: send_rtpp_command(): can't send command to a RTP proxy
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: ERROR: rtpproxy-ng [rtpproxy.c:1549]: send_rtpp_command(): proxy udp:127.0.0.1:2223 does not respond, disable it
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: ERROR: rtpproxy-ng [rtpproxy.c:1419]: rtpp_test(): proxy did not respond to ping
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: INFO: tls [tls_domain.c:190]: fill_missing(): TLSs: tls_method=9
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: INFO: tls [tls_domain.c:202]: fill_missing(): TLSs: certificate='/usr/local/etc/kamailio/Kam_CertOnly.pem'
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: INFO: tls [tls_domain.c:209]: fill_missing(): TLSs: ca_list='(null)'
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: INFO: tls [tls_domain.c:216]: fill_missing(): TLSs: crl='(null)'
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: INFO: tls [tls_domain.c:220]: fill_missing(): TLSs: require_certificate=0
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: INFO: tls [tls_domain.c:227]: fill_missing(): TLSs: cipher_list='(null)'
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: INFO: tls [tls_domain.c:234]: fill_missing(): TLSs: private_key='/usr/local/etc/kamailio/Kam_KeyOnly.pem'
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: INFO: tls [tls_domain.c:238]: fill_missing(): TLSs: verify_certificate=0
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: INFO: tls [tls_domain.c:241]: fill_missing(): TLSs: verify_depth=9
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: INFO: tls [tls_domain.c:579]: set_verification(): TLSs: No client certificate required and no checks performed
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: INFO: tls [tls_domain.c:190]: fill_missing(): TLSc: tls_method=9
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: INFO: tls [tls_domain.c:202]: fill_missing(): TLSc: certificate='(null)'
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: INFO: tls [tls_domain.c:209]: fill_missing(): TLSc: ca_list='/usr/local/etc/kamailio/RS001738_CA.pem'
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: INFO: tls [tls_domain.c:216]: fill_missing(): TLSc: crl='(null)'
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: INFO: tls [tls_domain.c:220]: fill_missing(): TLSc: require_certificate=1
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: INFO: tls [tls_domain.c:227]: fill_missing(): TLSc: cipher_list='(null)'
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: INFO: tls [tls_domain.c:234]: fill_missing(): TLSc: private_key='(null)'
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: INFO: tls [tls_domain.c:238]: fill_missing(): TLSc: verify_certificate=1
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: INFO: tls [tls_domain.c:241]: fill_missing(): TLSc: verify_depth=9
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: INFO: tls [tls_domain.c:564]: set_verification(): TLSc: Server MUST present valid certificate
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2503]: ERROR: rtpproxy-ng [rtpproxy.c:1513]: send_rtpp_command(): can't send command to a RTP proxy
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: ERROR: rtpproxy-ng [rtpproxy.c:1513]: send_rtpp_command(): can't send command to a RTP proxy
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: ERROR: rtpproxy-ng [rtpproxy.c:1549]: send_rtpp_command(): proxy udp:127.0.0.1:2223 does not respond, disable it
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: ERROR: rtpproxy-ng [rtpproxy.c:1419]: rtpp_test(): proxy did not respond to ping
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2504]: ERROR: rtpproxy-ng [rtpproxy.c:1513]: send_rtpp_command(): can't send command to a RTP proxy
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2504]: ERROR: rtpproxy-ng [rtpproxy.c:1549]: send_rtpp_command(): proxy udp:127.0.0.1:2223 does not respond, disable it
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2504]: ERROR: rtpproxy-ng [rtpproxy.c:1419]: rtpp_test(): proxy did not respond to ping
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2503]: ERROR: rtpproxy-ng [rtpproxy.c:1549]: send_rtpp_command(): proxy udp:127.0.0.1:2223 does not respond, disable it
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2503]: ERROR: rtpproxy-ng [rtpproxy.c:1419]: rtpp_test(): proxy did not respond to ping
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2507]: ERROR: rtpproxy-ng [rtpproxy.c:1513]: send_rtpp_command(): can't send command to a RTP proxy
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2507]: ERROR: rtpproxy-ng [rtpproxy.c:1549]: send_rtpp_command(): proxy udp:127.0.0.1:2223 does not respond, disable it
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2507]: ERROR: rtpproxy-ng [rtpproxy.c:1419]: rtpp_test(): proxy did not respond to ping
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2506]: ERROR: rtpproxy-ng [rtpproxy.c:1513]: send_rtpp_command(): can't send command to a RTP proxy
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2506]: ERROR: rtpproxy-ng [rtpproxy.c:1549]: send_rtpp_command(): proxy udp:127.0.0.1:2223 does not respond, disable it
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2506]: ERROR: rtpproxy-ng [rtpproxy.c:1419]: rtpp_test(): proxy did not respond to ping
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2506]: INFO: ctl [io_listener.c:225]: io_listen_loop(): io_listen_loop: using epoll_lt io watch method (config)
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2510]: ERROR: rtpproxy-ng [rtpproxy.c:1513]: send_rtpp_command(): can't send command to a RTP proxy
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2510]: ERROR: rtpproxy-ng [rtpproxy.c:1549]: send_rtpp_command(): proxy udp:127.0.0.1:2223 does not respond, disable it
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2510]: ERROR: rtpproxy-ng [rtpproxy.c:1419]: rtpp_test(): proxy did not respond to ping
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2511]: ERROR: rtpproxy-ng [rtpproxy.c:1513]: send_rtpp_command(): can't send command to a RTP proxy
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2511]: ERROR: rtpproxy-ng [rtpproxy.c:1549]: send_rtpp_command(): proxy udp:127.0.0.1:2223 does not respond, disable it
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2511]: ERROR: rtpproxy-ng [rtpproxy.c:1419]: rtpp_test(): proxy did not respond to ping
Aug 29 18:12:02 localhost kernel: Registering xt_MEDIAPROXY module - version undefined
Aug 29 18:12:03 localhost rtpengine[2515]: Generating new DTLS certificate
Aug 29 18:12:03 localhost rtpengine[2516]: Startup complete, version undefined
Aug 29 18:12:33 localhost /usr/local/sbin/kamailio[2510]: NOTICE: <script>: Enter main request route
Aug 29 18:12:33 localhost /usr/local/sbin/kamailio[2510]: INFO: <script>: Main request route OPTIONS
Aug 29 18:12:33 localhost /usr/local/sbin/kamailio[2507]: NOTICE: <script>: Enter main request route
Aug 29 18:12:33 localhost /usr/local/sbin/kamailio[2507]: INFO: <script>: Main request route OPTIONS
Aug 29 18:12:37 localhost /usr/local/sbin/kamailio[2507]: NOTICE: <script>: Enter main request route
Aug 29 18:12:37 localhost /usr/local/sbin/kamailio[2507]: INFO: <script>: Main request route INVITE
Aug 29 18:12:37 localhost /usr/local/sbin/kamailio[2507]: INFO: <script>: OUT_DIALOG_FROM_LYNCIT
Aug 29 18:12:37 localhost /usr/local/sbin/kamailio[2507]: ERROR: rtpproxy-ng [rtpproxy.c:1327]: rtpp_function_call(): no available proxies
Aug 29 18:12:39 localhost /usr/local/sbin/kamailio[2510]: NOTICE: <script>: Enter main request route
Aug 29 18:12:39 localhost /usr/local/sbin/kamailio[2510]: INFO: <script>: Main request route INVITE
Aug 29 18:12:39 localhost /usr/local/sbin/kamailio[2510]: INFO: <script>: OUT_DIALOG_TO_LYNCIT
Aug 29 18:12:39 localhost /usr/local/sbin/kamailio[2510]: INFO: <script>: sending to 192.168.2.106:5076 ERJ01
Aug 29 18:12:39 localhost /usr/local/sbin/kamailio[2510]: INFO: <script>: ERJ05 - out dialog to lyncit
Aug 29 18:12:39 localhost /usr/local/sbin/kamailio[2510]: INFO: <script>: ERJ06 - out dialog to lyncit INVITE
Aug 29 18:12:39 localhost /usr/local/sbin/kamailio[2510]: INFO: <script>: ERJ07 - out dialog to lyncit INVITE sdp
Aug 29 18:12:39 localhost /usr/local/sbin/kamailio[2510]: ERROR: rtpproxy-ng [rtpproxy.c:1327]: rtpp_function_call(): no available proxies
Aug 29 18:12:39 localhost /usr/local/sbin/kamailio[2510]: NOTICE: <script>: Enter main request route
Aug 29 18:12:39 localhost /usr/local/sbin/kamailio[2510]: INFO: <script>: Main request route ACK
Aug 29 18:12:39 localhost /usr/local/sbin/kamailio[2510]: INFO: <script>: IN_DIALOG_TO_LYNCIT
Aug 29 18:12:39 localhost /usr/local/sbin/kamailio[2510]: INFO: <script>: ERJ10 - IN_DIALOG_TO_LYNCIT NO sdp
Aug 29 18:12:39 localhost /usr/local/sbin/kamailio[2507]: NOTICE: <script>: Enter main request route
Aug 29 18:12:39 localhost /usr/local/sbin/kamailio[2507]: INFO: <script>: Main request route CANCEL
Aug 29 18:12:39 localhost /usr/local/sbin/kamailio[2507]: INFO: <script>: OUT_DIALOG_FROM_LYNCIT
Aug 29 18:12:44 localhost /usr/local/sbin/kamailio[2507]: NOTICE: <script>: Enter main request route
Aug 29 18:12:44 localhost /usr/local/sbin/kamailio[2507]: INFO: <script>: Main request route ACK
Aug 29 18:12:44 localhost /usr/local/sbin/kamailio[2507]: INFO: <script>: IN_DIALOG_FROM_LYNCIT

from rtpengine.

rfuchs commented on June 24, 2024

Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: ERROR: rtpproxy-ng [rtpproxy.c:1513]: send_rtpp_command(): can't send command to a RTP proxy
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: ERROR: rtpproxy-ng [rtpproxy.c:1549]: send_rtpp_command(): proxy udp:127.0.0.1:2223 does not respond, disable it
Aug 29 18:12:02 localhost /usr/local/sbin/kamailio[2499]: ERROR: rtpproxy-ng [rtpproxy.c:1419]: rtpp_test(): proxy did not respond to ping

This means just what I've explained. Kamailio tries to send a ping to rtpengine and doesn't receive a reply. Either the rtpengine daemon isn't running, or it's listening on the wrong interface or port, or something is blocking the pings from getting through.

from rtpengine.

edjames99 commented on June 24, 2024

OK thanks for that - I've now got past this issue (not quite sure how) and can see the sdp being modified but I'm getting no audio on the call inbound to RTPEngine (this used to work) and also still nothing on the outbound call. I looked at the final packet stats and it looks like media port 30010 and 30004 are both mapping to 192.1682.106:33044. I think that 30004 should map to 192.168.2.106:33488 given that 30005 maps to 192.168.2.106:33489, does that sound right or should two RTPEngine ports map to the same LyncIT port ?

Thanks - I'm probably driving you nuts I'm sorry about that, there's just a lot of pressure to get it working.
Thanks again.

Aug 29 12:02:52 localhost rtpengine[27489]: [M2Y5M2NjMDI1MTYwMzkwZDQxYjgwZGQ0OGRhMzYwZWM.] Final packet stats:
Aug 29 12:02:52 localhost rtpengine[27489]: [M2Y5M2NjMDI1MTYwMzkwZDQxYjgwZGQ0OGRhMzYwZWM.] --- Tag 'd3ea304d2e', created 1:47 ago, in dialogue with 'ea5dff55'
Aug 29 12:02:52 localhost rtpengine[27489]: [M2Y5M2NjMDI1MTYwMzkwZDQxYjgwZGQ0OGRhMzYwZWM.] ------ Media #1, port 30010 <> 192.168.2.106:33044, 0 p, 0 b, 0 e
Aug 29 12:02:52 localhost rtpengine[27489]: [M2Y5M2NjMDI1MTYwMzkwZDQxYjgwZGQ0OGRhMzYwZWM.] ------ Media #1, port 30011 <> 192.168.2.106:33045 (RTCP), 0 p, 0 b, 0 e
Aug 29 12:02:52 localhost rtpengine[27489]: [M2Y5M2NjMDI1MTYwMzkwZDQxYjgwZGQ0OGRhMzYwZWM.] --- Tag '888a672ba', created 1:47 ago, in dialogue with 'ea5dff55'
Aug 29 12:02:52 localhost rtpengine[27489]: [M2Y5M2NjMDI1MTYwMzkwZDQxYjgwZGQ0OGRhMzYwZWM.] ------ Media #1, port 30004 <> 192.168.2.106:33044, 2111 p, 385717 b, 22204 e
Aug 29 12:02:52 localhost rtpengine[27489]: [M2Y5M2NjMDI1MTYwMzkwZDQxYjgwZGQ0OGRhMzYwZWM.] ------ Media #1, port 30005 <> 192.168.2.106:33489 (RTCP), 52 p, 2893 b, 0 e
Aug 29 12:02:52 localhost rtpengine[27489]: [M2Y5M2NjMDI1MTYwMzkwZDQxYjgwZGQ0OGRhMzYwZWM.] --- Tag 'ea5dff55', created 1:47 ago, in dialogue with 'd3ea304d2e'
Aug 29 12:02:52 localhost rtpengine[27489]: [M2Y5M2NjMDI1MTYwMzkwZDQxYjgwZGQ0OGRhMzYwZWM.] ------ Media #1, port 30008 <> 10.1.0.121:19030, 1859 p, 318158 b, 0 e
Aug 29 12:02:52 localhost rtpengine[27489]: [M2Y5M2NjMDI1MTYwMzkwZDQxYjgwZGQ0OGRhMzYwZWM.] ------ Media #1, port 30009 <> 10.1.0.121:19031 (RTCP), 7 p, 364 b, 0 e
Aug 29 12:02:52 localhost rtpengine[27489]: [6ca6e2c2-434c-495e-9190-259070f2f482] Final packet stats:
Aug 29 12:02:52 localhost rtpengine[27489]: [6ca6e2c2-434c-495e-9190-259070f2f482] --- Tag '0d45497d', created 1:50 ago, in dialogue with '2266cfdf66'
Aug 29 12:02:52 localhost rtpengine[27489]: [6ca6e2c2-434c-495e-9190-259070f2f482] ------ Media #1, port 30000 <> 10.1.0.121:19020, 282 p, 49813 b, 0 e
Aug 29 12:02:52 localhost rtpengine[27489]: [6ca6e2c2-434c-495e-9190-259070f2f482] ------ Media #1, port 30001 <> 10.1.0.121:19021 (RTCP), 7 p, 488 b, 0 e
Aug 29 12:02:52 localhost rtpengine[27489]: [6ca6e2c2-434c-495e-9190-259070f2f482] --- Tag '2266cfdf66', created 1:50 ago, in dialogue with '0d45497d'
Aug 29 12:02:52 localhost rtpengine[27489]: [6ca6e2c2-434c-495e-9190-259070f2f482] ------ Media #1, port 30002 <> 192.168.2.106:33042, 1799 p, 309269 b, 0 e
Aug 29 12:02:52 localhost rtpengine[27489]: [6ca6e2c2-434c-495e-9190-259070f2f482] ------ Media #1, port 30003 <> 192.168.2.106:33043 (RTCP), 101 p, 5472 b, 0 e

from rtpengine.

rfuchs commented on June 24, 2024

Well, normally they wouldn't, but what you have here (as before) is a call with apparently 3 participants. Since rtpengine expects (and only supports) 1-to-1 associations between endpoints, one of these participants is necessarily left hanging. It looks like you have the same situation as before, that the port reserved for one endpoint receives traffic from a different endpoint (overwriting the endpoint address received from signalling with the source address of the received packets), hence the duplicate addresses, while the other port doesn't receive anything. As mentioned before, I really don't know what the expected result here is.

You can try using the "asymmetric" flag, which disables learning of endpoint addresses, but other than that I don't have any other suggestions.

from rtpengine.

edjames99 commented on June 24, 2024

OK thanks for the explanation, I didn't realize it did the learning step as I was looking at your output (which I've copied below) from an earlier post but presumably this output is purely based on the signalling. I'll give the asymmetric flag a go.

rtpengine[2555]: [asdgahahadfghadf] Closing call due to timeout
Aug 28 15:44:57 tabasco rtpengine[2555]: [asdgahahadfghadf] Final packet stats:
Aug 28 15:44:57 tabasco rtpengine[2555]: [asdgahahadfghadf] --- Tag '50ad6ca53', created 1:00 ago, in dialogue with 'd27bb023'
Aug 28 15:44:57 tabasco rtpengine[2555]: [asdgahahadfghadf] ------ Media #1, port 30006 <> 192.168.2.106:33044, 0 p, 0 b, 0 e
Aug 28 15:44:57 tabasco rtpengine[2555]: [asdgahahadfghadf] ------ Media #1, port 30007 <> 192.168.2.106:33045 (RTCP), 0 p, 0 b, 0 e
Aug 28 15:44:57 tabasco rtpengine[2555]: [asdgahahadfghadf] --- Tag '156b2a6f9c', created 1:07 ago, in dialogue with 'd27bb023'
Aug 28 15:44:57 tabasco rtpengine[2555]: [asdgahahadfghadf] ------ Media #1, port 30000 <> 192.168.2.106:33488, 0 p, 0 b, 0 e
Aug 28 15:44:57 tabasco rtpengine[2555]: [asdgahahadfghadf] ------ Media #1, port 30001 <> 192.168.2.106:33489 (RTCP), 0 p, 0 b, 0 e
Aug 28 15:44:57 tabasco rtpengine[2555]: [asdgahahadfghadf] --- Tag 'd27bb023', created 1:07 ago, in dialogue with '50ad6ca53'
Aug 28 15:44:57 tabasco rtpengine[2555]: [asdgahahadfghadf] ------ Media #1, port 30004 <> 10.1.0.121:19080, 0 p, 0 b, 0 e
Aug 28 15:44:57 tabasco rtpengine[2555]: [asdgahahadfghadf] ------ Media #1, port 30005 <> 10.1.0.121:19081 (RTCP), 0 p, 0 b

Talking to two of my colleagues about the expected behaviour, they think that the port latching should be initiated by the signalling (which it is being above) and then the expected behaviour would be for the rtpengine to latch onto the source port of the first packet it receives (which is what the engine is doing) and while the engine receives packets from this source port it should disregard any packets from any other source port. When it considers that it's no longer receiving packets from the first source port (based on some sort of internal engine timeout) it should then re-learn and latch onto the source port of the next packet and remain latched to that source port whilst it was receiving packets from that source port. It should be able to decrypt all the packets in both (or any number) streams.

I think that this would require the engine to hold a map of source port mapped to key (so it basically remembers all the keys it's ever been sent in the multiple 183s) so it could then decrypt both streams. Extracting the source port and looking up the key from the port -> key map should be quick (and certainly better than any logic which involved just trying the keys until one worked) so wouldn't have much overhead.

Do you think this is feasible to implement ?

Thanks for your help, it's much appreciated.

from rtpengine.

edjames99 commented on June 24, 2024

I changed rtpproxy_manage("froc+Sp"); to rtpproxy_manage("faoc+Sp"); to switch on the asymmetric flag but I got the same result (details below) in that it didn't keep the source port from the sip message:

Sep 1 11:22:15 localhost rtpengine[2500]: [MGNlYTQ5YTNlZDRkNDE5OWM4ZTQ3YzQ0NjY1M2M0OTE.] --- Tag '8156aa191', created 1:46 ago, in dialogue with 'b96ac65f'
Sep 1 11:22:15 localhost rtpengine[2500]: [MGNlYTQ5YTNlZDRkNDE5OWM4ZTQ3YzQ0NjY1M2M0OTE.] ------ Media #1, port 30126 <> 192.168.2.106:33044, 0 p, 0 b, 0 e
Sep 1 11:22:15 localhost rtpengine[2500]: [MGNlYTQ5YTNlZDRkNDE5OWM4ZTQ3YzQ0NjY1M2M0OTE.] ------ Media #1, port 30127 <> 192.168.2.106:33045 (RTCP), 0 p, 0 b, 0 e
Sep 1 11:22:15 localhost rtpengine[2500]: [MGNlYTQ5YTNlZDRkNDE5OWM4ZTQ3YzQ0NjY1M2M0OTE.] --- Tag '2ac6146613', created 1:47 ago, in dialogue with 'b96ac65f'
Sep 1 11:22:15 localhost rtpengine[2500]: [MGNlYTQ5YTNlZDRkNDE5OWM4ZTQ3YzQ0NjY1M2M0OTE.] ------ Media #1, port 30080 <> 192.168.2.106:33044, 2110 p, 385618 b, 1913 e
Sep 1 11:22:15 localhost rtpengine[2500]: [MGNlYTQ5YTNlZDRkNDE5OWM4ZTQ3YzQ0NjY1M2M0OTE.] ------ Media #1, port 30081 <> 192.168.2.106:33045 (RTCP), 48 p, 2709 b, 0 e

Have I set the flags incorrectly ?

Thanks

from rtpengine.

rfuchs commented on June 24, 2024

The "a" flag should be enough to disable learning of addresses, have you used it in all instances of rtpproxy_*() calls? You can verify it by looking at the offer/answer log lines of the rtpengine log, you should see the "asymmetric" flag there.

As for your suggestion, it is my understanding that this would go against what the SRTP RFC describes. RFC 3711 says that the cryptographic context (which holds the master key and session key) is determined by the destination address and port of a received SRTP packet, not the source address/port. IOW, if your testing tool sends packets to a particular port and encrypts them using a key advertised by a different endpoint (and a different port) then that's probably a bug in the testing tool. The RFC also says that a trial & error approach in finding the correct decryption key must not be used.

But leaving the SRTP issues aside, I'm not even sure which packets are supposed to be forwarded to where. Assuming that these endpoints were talking to each other directly, with no RTP proxy in between (and no SRTP involved, RTP only). Who ends up talking to who and on which ports? The endpoint making the original offer gets two answers from two different endpoints. Which one does it talk to? Which one does it send to and which one does it receive from?

from rtpengine.

edjames99 commented on June 24, 2024

Thanks for you help Richard, I think we need to go back to the testing tool people and ask them what they expect us to do. Your comments have really helped us to clarify the issue so thanks again.

from rtpengine.

edjames99 commented on June 24, 2024

Hi Richard,
We've now got the latest version of the Lync testing tool and it does not have the same problem with multiple 183 messages and multiple end points so that's good. When I run the same test as before I now get that early media works fine (based on an exchange of SDP descriptors in the INVITEs and 183 messages) but then the subsequent media fails in one direction although it works in the other.

Looking at the log I think this might be because the SDP is included in the 200 OK to the INVITEs (even though it's already been negotiated) and the RTPEngine is adding "a=crypto:4" to the SDP in the 200 OK to the INVITE for call id 4d6e1349-adf8-4c7c-9ab0-d9ea647de41c - search the log for "ERJ20 - 200 OK reply to INVITE from LYNCIT" for the details of this particular message. I assume this should be "a=crypto:1" and this is the only difference I can see between the SDP in the 183 and the SDP in 200 OK to the INVITE.
I've raised the question with the testing company we are working with (they're a MS approved company who administer the tests) as to why the testing tool sends out SDP in the 200 OK when it's already been negotiated in the 183 and indeed expects to receive a SDP in the 200 OK when it's already received it in the 183 and they say it's not illegal.
Here's the full log file contents - any help you could give would be greatly appreciated.

Sep 23 09:54:22 localhost /usr/local/sbin/kamailio[2519]: INFO: <script>: OUT_DIALOG_FROM_LYNCIT
Sep 23 09:54:22 localhost rtpengine[2528]: Got valid command from 127.0.0.1:39491: offer - { "sdp": "v=0#015#012o=- 0 0 IN IP4 192.168.2.106#015#012s=session#015#012c=IN IP4 192.168.2.106#015#012b=CT:1000#015#012t=0 0#015#012m=audio 33042 RTP/SAVP 0 8 97 101 13#015#012c=IN IP4 192.168.2.106#015#012a=rtcp:33043#015#012a=sendrecv#015#012a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:GqYOpB5gOYwN3fu0KcbyeJL1FQaPGVlDbPWkYKUr|2^31|1:1#015#012a=crypto:2 AES_CM_128_HMAC_SHA1_80 inline:uu7W0wc9jyepJFB3Nn0CT62WrOgnR/IZRYr1x36s|2^31#015#012a=rtpmap:0 PCMU/8000#015#012a=rtpmap:8 PCMA/8000#015#012a=label:main-audio#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=rtpmap:13 CN/8000#015#012", "ICE": "remove", "flags": [ "force", "asymmetric", "trust-address" ], "replace": [ "origin", "session-connection" ], "transport-protocol": "RTP/AVP", "call-id": "4d6e1349-adf8-4c7c-9ab0-d9ea647de41c", "received-from": [ "IP4", "192.168.2.106" ], "from-tag": "9dc491dee", "command": "offer" }
Sep 23 09:54:22 localhost rtpengine[2528]: ERJ LOG_ERROR parse crypto 1 31
Sep 23 09:54:22 localhost rtpengine[2528]: ERJ LOG_INFO parse crypto 1 31
Sep 23 09:54:22 localhost rtpengine[2528]: ERJ parse crypto 2 2147483648
Sep 23 09:54:22 localhost rtpengine[2528]: ERJ LOG_ERROR parse crypto 1 31
Sep 23 09:54:22 localhost rtpengine[2528]: ERJ LOG_INFO parse crypto 1 31
Sep 23 09:54:22 localhost rtpengine[2528]: ERJ parse crypto 2 2147483648
Sep 23 09:54:22 localhost rtpengine[2528]: [4d6e1349-adf8-4c7c-9ab0-d9ea647de41c] Creating new call
Sep 23 09:54:22 localhost rtpengine[2528]: [4d6e1349-adf8-4c7c-9ab0-d9ea647de41c] Returning to SIP proxy: d3:sdp325:v=0#015#012o=- 0 0 IN IP4 10.1.0.127#015#012s=session#015#012c=IN IP4 10.1.0.127#015#012b=CT:1000#015#012t=0 0#015#012m=audio 30004 RTP/AVP 0 8 97 101 13#015#012c=IN IP4 10.1.0.127#015#012a=rtpmap:0 PCMU/8000#015#012a=rtpmap:8 PCMA/8000#015#012a=label:main-audio#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=rtpmap:13 CN/8000#015#012a=sendrecv#015#012a=rtcp:30005#015#0126:result2:oke
Sep 23 09:54:24 localhost /usr/local/sbin/kamailio[2519]: NOTICE: <script>: Enter main request route
Sep 23 09:54:24 localhost /usr/local/sbin/kamailio[2519]: INFO: <script>: Main request route INVITE
Sep 23 09:54:24 localhost /usr/local/sbin/kamailio[2519]: INFO: <script>: OUT_DIALOG_TO_LYNCIT
Sep 23 09:54:24 localhost /usr/local/sbin/kamailio[2519]: INFO: <script>: sending to 192.168.2.106:5076 ERJ01
Sep 23 09:54:24 localhost /usr/local/sbin/kamailio[2519]: INFO: <script>: ERJ05 - out dialog to lyncit
Sep 23 09:54:24 localhost /usr/local/sbin/kamailio[2519]: INFO: <script>: ERJ06 - out dialog to lyncit INVITE
Sep 23 09:54:24 localhost /usr/local/sbin/kamailio[2519]: INFO: <script>: ERJ07 - out dialog to lyncit INVITE sdp
Sep 23 09:54:24 localhost rtpengine[2528]: Got valid command from 127.0.0.1:39491: offer - { "sdp": "v=0#015#012o=Redwood_INX 320648 320648 IN IP4 10.1.0.121#015#012s=Redwood Media Server#015#012c=IN IP4 10.1.0.121#015#012t=0 0#015#012m=audio 20170 RTP/AVP 8 97 96 13#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:96 telephone-event/8000#015#012a=fmtp:96 0-16#015#012a=rtpmap:13 CN/8000#015#012a=ptime:20#015#012a=sendrecv#015#012a=rtcp:20171#015#012a=label:main-audio#015#012", "ICE": "force", "flags": [ "force", "asymmetric", "trust-address" ], "replace": [ "origin", "session-connection" ], "transport-protocol": "RTP/SAVP", "call-id": "Y2JmYTY4ZmRlYzk2MGZjZDkwZTdlZjgwZTBiNjhhZjk.", "received-from": [ "IP4", "10.1.0.119" ], "from-tag": "0e531155", "command": "offer" }
Sep 23 09:54:24 localhost rtpengine[2528]: [Y2JmYTY4ZmRlYzk2MGZjZDkwZTdlZjgwZTBiNjhhZjk.] Creating new call
Sep 23 09:54:24 localhost rtpengine[2528]: [Y2JmYTY4ZmRlYzk2MGZjZDkwZTdlZjgwZTBiNjhhZjk.] Returning to SIP proxy: d3:sdp714:v=0#015#012o=Redwood_INX 320648 320648 IN IP4 10.1.0.127#015#012s=Redwood Media Server#015#012c=IN IP4 10.1.0.127#015#012t=0 0#015#012a=ice-lite#015#012m=audio 30008 RTP/SAVP 8 97 96 13#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:96 telephone-event/8000#015#012a=fmtp:96 0-16#015#012a=rtpmap:13 CN/8000#015#012a=ptime:20#015#012a=label:main-audio#015#012a=sendrecv#015#012a=rtcp:30009#015#012a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:L9fzPeOVDwE+WC+Cbs4E5cDY97HrHPn6YmbQSrhp#015#012a=setup:actpass#015#012a=fingerprint:sha-1 80:B7:6E:91:C8:83:08:1E:43:A7:9B:1E:3C:91:C4:56:4C:2E:74:79#015#012a=ice-ufrag:VJOUqfdv#015#012a=ice-pwd:BuKg24s2lnLgIqmWWsgM5ukYb6TB#015#012a=candidate:QDzGeemqUX7mhayw 1 UDP 2130706432 10.1.0.127 30008 typ host#015#012a=candidate:QDzGeemqUX7mhayw 2 UDP 2130706431 10.1.0.127 30009 typ host#015#0126:result2:oke
Sep 23 09:54:24 localhost /usr/local/sbin/kamailio[2522]: INFO: <script>: ERJ21 - 183 reply to INVITE to LYNCIT
Sep 23 09:54:24 localhost rtpengine[2528]: Got valid command from 127.0.0.1:56547: answer - { "sdp": "v=0#015#012o=- 0 0 IN IP4 192.168.2.106#015#012s=session#015#012c=IN IP4 192.168.2.106#015#012b=CT:1000#015#012t=0 0#015#012m=audio 33044 RTP/SAVP 8 97 96 13#015#012c=IN IP4 192.168.2.106#015#012a=rtcp:33045#015#012a=sendrecv#015#012a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:YxIwGUqyPuT+Y9/jiQbaQgM8C/4UQT+XL9sRjs3E|2^31|1:1#015#012a=rtpmap:8 PCMA/8000#015#012a=ptime:20#015#012a=label:main-audio#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:96 telephone-event/8000#015#012a=fmtp:96 0-16#015#012a=rtpmap:13 CN/8000#015#012", "ICE": "remove", "transport-protocol": "RTP/AVP", "call-id": "Y2JmYTY4ZmRlYzk2MGZjZDkwZTdlZjgwZTBiNjhhZjk.", "received-from": [ "IP4", "192.168.2.106" ], "from-tag": "0e531155", "to-tag": "df2f6ab058", "command": "answer" }
Sep 23 09:54:24 localhost rtpengine[2528]: ERJ LOG_ERROR parse crypto 1 31
Sep 23 09:54:24 localhost rtpengine[2528]: ERJ LOG_INFO parse crypto 1 31
Sep 23 09:54:24 localhost rtpengine[2528]: ERJ parse crypto 2 2147483648
Sep 23 09:54:24 localhost rtpengine[2528]: [Y2JmYTY4ZmRlYzk2MGZjZDkwZTdlZjgwZTBiNjhhZjk.] Returning to SIP proxy: d3:sdp316:v=0#015#012o=- 0 0 IN IP4 192.168.2.106#015#012s=session#015#012c=IN IP4 192.168.2.106#015#012b=CT:1000#015#012t=0 0#015#012m=audio 30010 RTP/AVP 8 97 96 13#015#012c=IN IP4 10.1.0.127#015#012a=rtpmap:8 PCMA/8000#015#012a=ptime:20#015#012a=label:main-audio#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:96 telephone-event/8000#015#012a=fmtp:96 0-16#015#012a=rtpmap:13 CN/8000#015#012a=sendrecv#015#012a=rtcp:30011#015#0126:result2:oke
Sep 23 09:54:24 localhost rtpengine[2528]: [4d6e1349-adf8-4c7c-9ab0-d9ea647de41c port 30004] SRTP output wanted, but no crypto suite was negotiated
Sep 23 09:54:24 localhost rtpengine[2528]: [4d6e1349-adf8-4c7c-9ab0-d9ea647de41c port 30005] SRTCP output wanted, but no crypto suite was negotiated
Sep 23 09:54:24 localhost rtpengine[2528]: [4d6e1349-adf8-4c7c-9ab0-d9ea647de41c port 30004] SRTP output wanted, but no crypto suite was negotiated
Sep 23 09:54:24 localhost rtpengine[2528]: [4d6e1349-adf8-4c7c-9ab0-d9ea647de41c port 30004] SRTP output wanted, but no crypto suite was negotiated
Sep 23 09:54:24 localhost rtpengine[2528]: [4d6e1349-adf8-4c7c-9ab0-d9ea647de41c port 30004] SRTP output wanted, but no crypto suite was negotiated
Sep 23 09:54:24 localhost rtpengine[2528]: [4d6e1349-adf8-4c7c-9ab0-d9ea647de41c port 30004] SRTP output wanted, but no crypto suite was negotiated
Sep 23 09:54:24 localhost rtpengine[2528]: [4d6e1349-adf8-4c7c-9ab0-d9ea647de41c port 30004] SRTP output wanted, but no crypto suite was negotiated
Sep 23 09:54:24 localhost rtpengine[2528]: [4d6e1349-adf8-4c7c-9ab0-d9ea647de41c port 30004] SRTP output wanted, but no crypto suite was negotiated
Sep 23 09:54:24 localhost rtpengine[2528]: [4d6e1349-adf8-4c7c-9ab0-d9ea647de41c port 30004] SRTP output wanted, but no crypto suite was negotiated
Sep 23 09:54:24 localhost rtpengine[2528]: [4d6e1349-adf8-4c7c-9ab0-d9ea647de41c port 30004] SRTP output wanted, but no crypto suite was negotiated
Sep 23 09:54:25 localhost rtpengine[2528]: [4d6e1349-adf8-4c7c-9ab0-d9ea647de41c port 30004] SRTP output wanted, but no crypto suite was negotiated
Sep 23 09:54:25 localhost /usr/local/sbin/kamailio[2519]: NOTICE: <script>: Enter main request route
Sep 23 09:54:25 localhost /usr/local/sbin/kamailio[2519]: INFO: <script>: Main request route PRACK
Sep 23 09:54:25 localhost /usr/local/sbin/kamailio[2519]: INFO: <script>: IN_DIALOG_TO_LYNCIT
Sep 23 09:54:25 localhost /usr/local/sbin/kamailio[2519]: INFO: <script>: ERJ08 - IN_DIALOG_TO_LYNCIT PRACK
Sep 23 09:54:25 localhost /usr/local/sbin/kamailio[2519]: INFO: <script>: ERJ10 - IN_DIALOG_TO_LYNCIT NO sdp
Sep 23 09:54:25 localhost /usr/local/sbin/kamailio[2522]: INFO: <script>: ERJ20 - 183 reply to INVITE from LYNCIT
Sep 23 09:54:25 localhost rtpengine[2528]: Got valid command from 127.0.0.1:56547: answer - { "sdp": "v=0#015#012o=Redwood_INX 320633 320633 IN IP4 10.1.0.121#015#012s=Redwood Media Server#015#012c=IN IP4 10.1.0.121#015#012t=0 0#015#012m=audio 20160 RTP/AVP 8 97 101 13#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=rtpmap:13 CN/8000#015#012a=sendrecv#015#012", "ICE": "force", "flags": [ "force", "asymmetric", "trust-address" ], "replace": [ "origin", "session-connection" ], "transport-protocol": "RTP/SAVP", "call-id": "4d6e1349-adf8-4c7c-9ab0-d9ea647de41c", "received-from": [ "IP4", "10.1.0.119" ], "from-tag": "9dc491dee", "to-tag": "b0129639", "command": "answer" }
Sep 23 09:54:25 localhost rtpengine[2528]: [4d6e1349-adf8-4c7c-9ab0-d9ea647de41c] Returning to SIP proxy: d3:sdp587:v=0#015#012o=Redwood_INX 320633 320633 IN IP4 10.1.0.127#015#012s=Redwood Media Server#015#012c=IN IP4 10.1.0.127#015#012t=0 0#015#012a=ice-lite#015#012m=audio 30006 RTP/SAVP 8 97 101 13#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=rtpmap:13 CN/8000#015#012a=sendrecv#015#012a=rtcp:30007#015#012a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:ktbqt4Z2C7hxLu9QEf4npfgZM+xuJ7EN09+VZk36#015#012a=ice-ufrag:3bf86NUi#015#012a=ice-pwd:oLUXYThrA1ecHu16PjR7LHfNQuTX#015#012a=candidate:QDzGeemqUX7mhayw 1 UDP 2130706432 10.1.0.127 30006 typ host#015#012a=candidate:QDzGeemqUX7mhayw 2 UDP 2130706431 10.1.0.127 30007 typ host#015#0126:result2:oke
Sep 23 09:54:25 localhost /usr/local/sbin/kamailio[2519]: NOTICE: <script>: Enter main request route
Sep 23 09:54:25 localhost /usr/local/sbin/kamailio[2519]: INFO: <script>: Main request route PRACK
Sep 23 09:54:25 localhost /usr/local/sbin/kamailio[2519]: INFO: <script>: IN_DIALOG_FROM_LYNCIT
Sep 23 09:54:28 localhost kernel: alg: No test for __gcm-aes-aesni (__driver-gcm-aes-aesni)
Sep 23 09:54:28 localhost kernel: padlock: VIA PadLock not detected.
Sep 23 09:54:33 localhost /usr/local/sbin/kamailio[2519]: INFO: <script>: ERJ21 - 200 OK reply to INVITE to LYNCIT
Sep 23 09:54:33 localhost rtpengine[2528]: Got valid command from 127.0.0.1:39491: answer - { "sdp": "v=0#015#012o=- 0 0 IN IP4 192.168.2.106#015#012s=session#015#012c=IN IP4 192.168.2.106#015#012b=CT:1000#015#012t=0 0#015#012m=audio 33044 RTP/SAVP 8 97 96 13#015#012c=IN IP4 192.168.2.106#015#012a=rtcp:33045#015#012a=sendrecv#015#012a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:YxIwGUqyPuT+Y9/jiQbaQgM8C/4UQT+XL9sRjs3E|2^31|1:1#015#012a=rtpmap:8 PCMA/8000#015#012a=ptime:20#015#012a=label:main-audio#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:96 telephone-event/8000#015#012a=fmtp:96 0-16#015#012a=rtpmap:13 CN/8000#015#012", "ICE": "remove", "transport-protocol": "RTP/AVP", "call-id": "Y2JmYTY4ZmRlYzk2MGZjZDkwZTdlZjgwZTBiNjhhZjk.", "received-from": [ "IP4", "192.168.2.106" ], "from-tag": "0e531155", "to-tag": "df2f6ab058", "command": "answer" }
Sep 23 09:54:33 localhost rtpengine[2528]: ERJ LOG_ERROR parse crypto 1 31
Sep 23 09:54:33 localhost rtpengine[2528]: ERJ LOG_INFO parse crypto 1 31
Sep 23 09:54:33 localhost rtpengine[2528]: ERJ parse crypto 2 2147483648
Sep 23 09:54:33 localhost rtpengine[2528]: [Y2JmYTY4ZmRlYzk2MGZjZDkwZTdlZjgwZTBiNjhhZjk.] Returning to SIP proxy: d3:sdp316:v=0#015#012o=- 0 0 IN IP4 192.168.2.106#015#012s=session#015#012c=IN IP4 192.168.2.106#015#012b=CT:1000#015#012t=0 0#015#012m=audio 30010 RTP/AVP 8 97 96 13#015#012c=IN IP4 10.1.0.127#015#012a=rtpmap:8 PCMA/8000#015#012a=ptime:20#015#012a=label:main-audio#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:96 telephone-event/8000#015#012a=fmtp:96 0-16#015#012a=rtpmap:13 CN/8000#015#012a=sendrecv#015#012a=rtcp:30011#015#0126:result2:oke
Sep 23 09:54:33 localhost /usr/local/sbin/kamailio[2522]: INFO: <script>: ERJ20 - 200 OK reply to INVITE from LYNCIT
Sep 23 09:54:33 localhost /usr/local/sbin/kamailio[2519]: NOTICE: <script>: Enter main request route
Sep 23 09:54:33 localhost /usr/local/sbin/kamailio[2519]: INFO: <script>: Main request route ACK
Sep 23 09:54:33 localhost /usr/local/sbin/kamailio[2519]: INFO: <script>: IN_DIALOG_TO_LYNCIT
Sep 23 09:54:33 localhost /usr/local/sbin/kamailio[2519]: INFO: <script>: ERJ10 - IN_DIALOG_TO_LYNCIT NO sdp
Sep 23 09:54:33 localhost rtpengine[2528]: Got valid command from 127.0.0.1:56547: answer - { "sdp": "v=0#015#012o=Redwood_INX 320633 320633 IN IP4 10.1.0.121#015#012s=Redwood Media Server#015#012c=IN IP4 10.1.0.121#015#012t=0 0#015#012m=audio 20160 RTP/AVP 8 97 101 13#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=rtpmap:13 CN/8000#015#012a=sendrecv#015#012", "ICE": "force", "flags": [ "force", "asymmetric", "trust-address" ], "replace": [ "origin", "session-connection" ], "transport-protocol": "RTP/SAVP", "call-id": "4d6e1349-adf8-4c7c-9ab0-d9ea647de41c", "received-from": [ "IP4", "10.1.0.119" ], "from-tag": "9dc491dee", "to-tag": "b0129639", "command": "answer" }
Sep 23 09:54:33 localhost rtpengine[2528]: [4d6e1349-adf8-4c7c-9ab0-d9ea647de41c] Returning to SIP proxy: d3:sdp587:v=0#015#012o=Redwood_INX 320633 320633 IN IP4 10.1.0.127#015#012s=Redwood Media Server#015#012c=IN IP4 10.1.0.127#015#012t=0 0#015#012a=ice-lite#015#012m=audio 30006 RTP/SAVP 8 97 101 13#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:97 red/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=rtpmap:13 CN/8000#015#012a=sendrecv#015#012a=rtcp:30007#015#012a=crypto:4 AES_CM_128_HMAC_SHA1_80 inline:ktbqt4Z2C7hxLu9QEf4npfgZM+xuJ7EN09+VZk36#015#012a=ice-ufrag:3bf86NUi#015#012a=ice-pwd:oLUXYThrA1ecHu16PjR7LHfNQuTX#015#012a=candidate:QDzGeemqUX7mhayw 1 UDP 2130706432 10.1.0.127 30006 typ host#015#012a=candidate:QDzGeemqUX7mhayw 2 UDP 2130706431 10.1.0.127 30007 typ host#015#0126:result2:oke
Sep 23 09:54:33 localhost /usr/local/sbin/kamailio[2522]: NOTICE: <script>: Enter main request route
Sep 23 09:54:33 localhost /usr/local/sbin/kamailio[2522]: INFO: <script>: Main request route ACK
Sep 23 09:54:33 localhost /usr/local/sbin/kamailio[2522]: INFO: <script>: IN_DIALOG_FROM_LYNCIT
Sep 23 09:55:20 localhost /usr/local/sbin/kamailio[2519]: NOTICE: <script>: Enter main request route
Sep 23 09:55:20 localhost /usr/local/sbin/kamailio[2519]: INFO: <script>: Main request route OPTIONS
Sep 23 09:55:20 localhost /usr/local/sbin/kamailio[2522]: NOTICE: <script>: Enter main request route
Sep 23 09:55:20 localhost /usr/local/sbin/kamailio[2522]: INFO: <script>: Main request route OPTIONS
Sep 23 09:55:27 localhost rtpengine[2528]: [Y2JmYTY4ZmRlYzk2MGZjZDkwZTdlZjgwZTBiNjhhZjk. port 30008] Error parsing RTP header: invalid header version
Sep 23 09:55:46 localhost rtpengine[2528]: [Y2JmYTY4ZmRlYzk2MGZjZDkwZTdlZjgwZTBiNjhhZjk. port 30008] Error parsing RTP header: invalid header version
Sep 23 09:56:05 localhost rtpengine[2528]: [Y2JmYTY4ZmRlYzk2MGZjZDkwZTdlZjgwZTBiNjhhZjk. port 30008] Error parsing RTP header: invalid header version
Sep 23 09:56:20 localhost /usr/local/sbin/kamailio[2522]: NOTICE: <script>: Enter main request route
Sep 23 09:56:20 localhost /usr/local/sbin/kamailio[2522]: INFO: <script>: Main request route OPTIONS
Sep 23 09:56:20 localhost /usr/local/sbin/kamailio[2519]: NOTICE: <script>: Enter main request route
Sep 23 09:56:20 localhost /usr/local/sbin/kamailio[2519]: INFO: <script>: Main request route OPTIONS
Sep 23 09:56:24 localhost rtpengine[2528]: [Y2JmYTY4ZmRlYzk2MGZjZDkwZTdlZjgwZTBiNjhhZjk. port 30008] Error parsing RTP header: invalid header version
Sep 23 09:56:43 localhost rtpengine[2528]: [Y2JmYTY4ZmRlYzk2MGZjZDkwZTdlZjgwZTBiNjhhZjk. port 30008] Error parsing RTP header: invalid header version
Sep 23 09:57:02 localhost rtpengine[2528]: [Y2JmYTY4ZmRlYzk2MGZjZDkwZTdlZjgwZTBiNjhhZjk. port 30008] Error parsing RTP header: invalid header version
Sep 23 09:57:20 localhost /usr/local/sbin/kamailio[2519]: NOTICE: <script>: Enter main request route
Sep 23 09:57:20 localhost /usr/local/sbin/kamailio[2519]: INFO: <script>: Main request route OPTIONS
Sep 23 09:57:20 localhost /usr/local/sbin/kamailio[2522]: NOTICE: <script>: Enter main request route
Sep 23 09:57:20 localhost /usr/local/sbin/kamailio[2522]: INFO: <script>: Main request route OPTIONS
Sep 23 09:57:21 localhost rtpengine[2528]: [Y2JmYTY4ZmRlYzk2MGZjZDkwZTdlZjgwZTBiNjhhZjk. port 30008] Error parsing RTP header: invalid header version
Sep 23 09:57:40 localhost rtpengine[2528]: [Y2JmYTY4ZmRlYzk2MGZjZDkwZTdlZjgwZTBiNjhhZjk. port 30008] Error parsing RTP header: invalid header version
Sep 23 09:57:59 localhost rtpengine[2528]: [Y2JmYTY4ZmRlYzk2MGZjZDkwZTdlZjgwZTBiNjhhZjk. port 30008] Error parsing RTP header: invalid header version
Sep 23 09:58:04 localhost /usr/local/sbin/kamailio[2522]: NOTICE: <script>: Enter main request route
Sep 23 09:58:04 localhost /usr/local/sbin/kamailio[2522]: INFO: <script>: Main request route BYE
Sep 23 09:58:04 localhost /usr/local/sbin/kamailio[2522]: INFO: <script>: IN_DIALOG_FROM_LYNCIT
Sep 23 09:58:05 localhost /usr/local/sbin/kamailio[2522]: NOTICE: <script>: Enter main request route
Sep 23 09:58:05 localhost /usr/local/sbin/kamailio[2522]: INFO: <script>: Main request route BYE
Sep 23 09:58:05 localhost /usr/local/sbin/kamailio[2522]: INFO: <script>: IN_DIALOG_TO_LYNCIT
Sep 23 09:58:05 localhost /usr/local/sbin/kamailio[2522]: INFO: <script>: ERJ10 - IN_DIALOG_TO_LYNCIT NO sdp
Sep 23 09:58:20 localhost /usr/local/sbin/kamailio[2522]: NOTICE: <script>: Enter main request route
Sep 23 09:58:20 localhost /usr/local/sbin/kamailio[2522]: INFO: <script>: Main request route OPTIONS
Sep 23 09:58:20 localhost /usr/local/sbin/kamailio[2519]: NOTICE: <script>: Enter main request route
Sep 23 09:58:20 localhost /usr/local/sbin/kamailio[2519]: INFO: <script>: Main request route OPTIONS
Sep 23 09:59:04 localhost rtpengine[2528]: Closing call branch due to timeout
Sep 23 09:59:04 localhost rtpengine[2528]: [4d6e1349-adf8-4c7c-9ab0-d9ea647de41c] Final packet stats:
Sep 23 09:59:04 localhost rtpengine[2528]: [4d6e1349-adf8-4c7c-9ab0-d9ea647de41c] --- Tag 'b0129639', created 4:42 ago, in dialogue with '9dc491dee'
Sep 23 09:59:04 localhost rtpengine[2528]: [4d6e1349-adf8-4c7c-9ab0-d9ea647de41c] ------ Media #1, port 30006 <> 192.168.2.106:33042, 10499 p, 2246585 b, 0 e
Sep 23 09:59:04 localhost rtpengine[2528]: [4d6e1349-adf8-4c7c-9ab0-d9ea647de41c] ------ Media #1, port 30007 <> 192.168.2.106:33043 (RTCP), 142 p, 11996 b, 0 e
Sep 23 09:59:04 localhost rtpengine[2528]: [4d6e1349-adf8-4c7c-9ab0-d9ea647de41c] --- Tag '9dc491dee', created 4:42 ago, in dialogue with 'b0129639'
Sep 23 09:59:04 localhost rtpengine[2528]: [4d6e1349-adf8-4c7c-9ab0-d9ea647de41c] ------ Media #1, port 30004 <> 10.1.0.121:20160, 2064 p, 449261 b, 0 e
Sep 23 09:59:04 localhost rtpengine[2528]: [4d6e1349-adf8-4c7c-9ab0-d9ea647de41c] ------ Media #1, port 30005 <> 10.1.0.121:20161 (RTCP), 30 p, 2178 b, 0 e
Sep 23 09:59:06 localhost rtpengine[2528]: Closing call branch due to timeout
Sep 23 09:59:06 localhost rtpengine[2528]: [Y2JmYTY4ZmRlYzk2MGZjZDkwZTdlZjgwZTBiNjhhZjk.] Final packet stats:
Sep 23 09:59:06 localhost rtpengine[2528]: [Y2JmYTY4ZmRlYzk2MGZjZDkwZTdlZjgwZTBiNjhhZjk.] --- Tag 'df2f6ab058', created 4:42 ago, in dialogue with '0e531155'
Sep 23 09:59:06 localhost rtpengine[2528]: [Y2JmYTY4ZmRlYzk2MGZjZDkwZTdlZjgwZTBiNjhhZjk.] ------ Media #1, port 30010 <> 10.1.0.121:20170, 10535 p, 2350648 b, 0 e
Sep 23 09:59:06 localhost rtpengine[2528]: [Y2JmYTY4ZmRlYzk2MGZjZDkwZTdlZjgwZTBiNjhhZjk.] ------ Media #1, port 30011 <> 10.1.0.121:20171 (RTCP), 27 p, 1926 b, 0 e
Sep 23 09:59:06 localhost rtpengine[2528]: [Y2JmYTY4ZmRlYzk2MGZjZDkwZTdlZjgwZTBiNjhhZjk.] --- Tag '0e531155', created 4:42 ago, in dialogue with 'df2f6ab058'
Sep 23 09:59:06 localhost rtpengine[2528]: [Y2JmYTY4ZmRlYzk2MGZjZDkwZTdlZjgwZTBiNjhhZjk.] ------ Media #1, port 30008 <> 192.168.2.106:33044, 2117 p, 437078 b, 0 e
Sep 23 09:59:06 localhost rtpengine[2528]: [Y2JmYTY4ZmRlYzk2MGZjZDkwZTdlZjgwZTBiNjhhZjk.] ------ Media #1, port 30009 <> 192.168.2.106:33045 (RTCP), 154 p, 13512 b, 0 e

from rtpengine.

rfuchs commented on June 24, 2024

Yes you're right, this seems to be a bug. I'll investigate.

from rtpengine.

rfuchs commented on June 24, 2024

However, I'm unable to reproduce this. If I replay the exact same signalling messages as I see in your log, the "answer" consistently comes back with a "crypto:1 ..." tag as it should, no matter how many times I repeat the answer.

Does it always come back as "crypto:4" for you, or is the number changing or random?

from rtpengine.

edjames99 commented on June 24, 2024

Thanks Richard, I got the latest source and it gives me "crypto:1..." so thanks for your help. I believe that the RTPEngine is now working for both call directions. The LyncIT testing tool is still failing the test but I think this is due to an issue with the tool itself so I'm closing this issue.

from rtpengine.

No RTP/SRTP Sent about rtpengine HOT 50 CLOSED

Comments (50)

Related Issues (20)

Recommend Projects

React

Vue.js

Typescript

TensorFlow

Django

Laravel

D3

Recommend Topics

javascript

web

server

Machine learning

Visualization

Game

Recommend Org

Facebook

Microsoft

Google

Alibaba

D3

Tencent