aTalk Jingle media call has ported to be compatible with smack 4.4.5 JingleManager implementation. So far system testings show that there are no problem with media call (video/audio) setup between two android devices installed with aTalk. aTalk embedded the transport-candidates in the session-initiate and session-accept stanzas.
However when a call is initiated from conversations client installed on a Samsung SM-J730 device to a aTalk client installed on Note-10 (SM-N975F); following problems are observed (see logcat below).
In conversations unique implementation, all transport candidates are being sent one at a time after the session-initiate stanza is sent. From logcat result, it takes approx 46~61 mS turn around time for aTalk to register JingleSession Handler after session-initiate is received. Prior to this, 3 transport-candidates are already being sent from conversations. 2 of the 3 transport-candidates are not being handled, causing the call setup to fail. All xmpp clients without JingleMessage implementations will experience this race conditions problem. Expected the problem to be worst if the above devices setup are swapped i.e. from fast to a slow android devices.
aTalk needs to modify to use JingleMessage protocol to perform JingleSession Handler registration.
Note: It was also observed that conversations sends transport-candidates prior to session-initiate. Not sure if this happens only with JingleMessage protocol support.
2022-04-11 04:30:10.419 19984-20332/org.atalk.android D/SMACK: RECV (0):
<iq xml:lang='en' to='swordfish@atalk.sytes.net/atalk' from='parrot@atalk.sytes.net/Conversations.lxYf' type='set' id='UHoKGByU7SCQ'>
<jingle xmlns='urn:xmpp:jingle:1' sid='2rV9iOj12EjXNxEOcOyHiQ' action='session-initiate'>
......
2022-04-11 04:30:10.434 19984-20332/org.atalk.android I/aTalk: [276] org.jivesoftware.smackx.jingle.provider.JingleProvider.parse() Found provider for EE<group urn:xmpp:jingle:apps:grouping:0/>
2022-04-11 04:30:10.480 19984-20551/org.atalk.android I/aTalk: [329] org.jivesoftware.smackx.jingle_rtp.JingleCallSessionImpl.<init>() Register JingleSession Handler: parrot@atalk.sytes.net/Conversations.lxYf 2rV9iOj12EjXNxEOcOyHiQ
2022-04-11 04:30:10.510 19984-20550/org.atalk.android W/aTalk: [328] org.jivesoftware.smackx.jingle.JingleManager.handleIQRequest() Unknown session: (uaYdMxlWq-qm) 2rV9iOj12EjXNxEOcOyHiQ
2022-04-11 04:30:10.543 19984-20552/org.atalk.android W/aTalk: [330] org.jivesoftware.smackx.jingle.JingleManager.handleIQRequest() Unknown session: (pMnH3lNqVfZD) 2rV9iOj12EjXNxEOcOyHiQ
============full logcat captured on Note-10 ============
2022-04-11 04:30:07.727 19984-20332/org.atalk.android D/SMACK: RECV (0):
<message xml:lang='en' to='swordfish@atalk.sytes.net' from='parrot@atalk.sytes.net/Conversations.lxYf' type='chat' id='jm-propose-2rV9iOj12EjXNxEOcOyHiQ'>
<propose xmlns='urn:xmpp:jingle-message:0' id='2rV9iOj12EjXNxEOcOyHiQ'>
<description xmlns='urn:xmpp:jingle:apps:rtp:1' media='audio'/>
</propose>
<request xmlns='urn:xmpp:receipts'/>
<store xmlns='urn:xmpp:hints'/>
</message>
2022-04-11 04:30:07.759 19984-20331/org.atalk.android D/SMACK: SENT (0):
<message to='parrot@atalk.sytes.net/Conversations.lxYf' type='chat'>
<received xmlns='urn:xmpp:receipts' id='jm-propose-2rV9iOj12EjXNxEOcOyHiQ'/>
</message>
2022-04-11 04:30:07.772 19984-20332/org.atalk.android D/SMACK: RECV (0):
<a h='51' xmlns='urn:xmpp:sm:3'/>
2022-04-11 04:30:09.154 19984-20331/org.atalk.android D/SMACK: SENT (0):
<message to='swordfish@atalk.sytes.net' type='chat'>
<accept xmlns='urn:xmpp:jingle-message:0' id='2rV9iOj12EjXNxEOcOyHiQ'/>
</message>
<r xmlns='urn:xmpp:sm:3'/>
2022-04-11 04:30:09.178 19984-20332/org.atalk.android D/SMACK: RECV (0):
<message xml:lang='en' to='swordfish@atalk.sytes.net' from='swordfish@atalk.sytes.net/atalk' type='chat'>
<accept xmlns='urn:xmpp:jingle-message:0' id='2rV9iOj12EjXNxEOcOyHiQ'/>
</message>
2022-04-11 04:30:09.194 19984-20331/org.atalk.android D/SMACK: SENT (0):
<message xml:lang='en' to='parrot@atalk.sytes.net/Conversations.lxYf' type='chat'>
<proceed xmlns='urn:xmpp:jingle-message:0' id='2rV9iOj12EjXNxEOcOyHiQ'/>
</message>
<r xmlns='urn:xmpp:sm:3'/>
2022-04-11 04:30:10.419 19984-20332/org.atalk.android D/SMACK: RECV (0):
<iq xml:lang='en' to='swordfish@atalk.sytes.net/atalk' from='parrot@atalk.sytes.net/Conversations.lxYf' type='set' id='UHoKGByU7SCQ'>
<jingle xmlns='urn:xmpp:jingle:1' sid='2rV9iOj12EjXNxEOcOyHiQ' action='session-initiate'>
<group xmlns='urn:xmpp:jingle:apps:grouping:0' semantics='BUNDLE'>
<content name='0'/>
</group>
<content name='0' creator='initiator'>
<description xmlns='urn:xmpp:jingle:apps:rtp:1' media='audio'>
<payload-type channels='2' name='opus' clockrate='48000' id='111'>
<parameter name='minptime' value='10'/>
<parameter name='useinbandfec' value='1'/>
<rtcp-fb xmlns='urn:xmpp:jingle:apps:rtp:rtcp-fb:0' type='transport-cc'/>
</payload-type>
<payload-type name='ISAC' clockrate='16000' id='103'/>
<payload-type name='G722' clockrate='8000' id='9'/>
<payload-type name='ILBC' clockrate='8000' id='102'/>
<payload-type name='PCMU' clockrate='8000' id='0'/>
<payload-type name='PCMA' clockrate='8000' id='8'/>
<payload-type name='CN' clockrate='16000' id='105'/>
<payload-type name='CN' clockrate='8000' id='13'/>
<payload-type name='telephone-event' clockrate='48000' id='110'/>
<payload-type name='telephone-event' clockrate='16000' id='113'/>
<payload-type name='telephone-event' clockrate='8000' id='126'/>
<rtp-hdrext xmlns='urn:xmpp:jingle:apps:rtp:rtp-hdrext:0' uri='urn:ietf:params:rtp-hdrext:ssrc-audio-level' id='1'/>
<rtp-hdrext xmlns='urn:xmpp:jingle:apps:rtp:rtp-hdrext:0' uri='http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time' id='2'/>
<rtp-hdrext xmlns='urn:xmpp:jingle:apps:rtp:rtp-hdrext:0' uri='http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01' id='3'/>
<rtp-hdrext xmlns='urn:xmpp:jingle:apps:rtp:rtp-hdrext:0' uri='urn:ietf:params:rtp-hdrext:sdes:mid' id='4'/>
<rtp-hdrext xmlns='urn:xmpp:jingle:apps:rtp:rtp-hdrext:0' uri='urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id' id='5'/>
<rtp-hdrext xmlns='urn:xmpp:jingle:apps:rtp:rtp-hdrext:0' uri='urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id' id='6'/>
<extmap-allow-mixed xmlns='urn:xmpp:jingle:apps:rtp:rtp-hdrext:0'/>
<source xmlns='urn:xmpp:jingle:apps:rtp:ssma:0' ssrc='3032658646'>
<parameter name='cname' value='3Z60XOqSG08ofAKa'/>
<parameter name='msid' value='- my-audio-track'/>
<parameter name='mslabel' value='-'/>
<parameter name='label' value='my-audio-track'/>
</source>
<rtcp-mux/>
</description>
<transport xmlns='urn:xmpp:jingle:transports:ice-udp:1' pwd='3uLJegIm1j87sIb3G320VK3m' ufrag='BDNh'>
<fingerprint xmlns='urn:xmpp:jingle:apps:dtls:0' setup='actpass' hash='sha-256'>
C8:99:50:D7:7F:EC:91:72:5E:58:F6:AF:08:16:8A:4A:93:64:26:EE:32:53:9D:3B:2B:4B:6A:55:C2:A8:F1:69
</fingerprint>
</transport>
</content>
</jingle>
</iq>
2022-04-11 04:30:10.434 19984-20332/org.atalk.android I/aTalk: [276] org.jivesoftware.smackx.jingle.provider.JingleProvider.parse() Found provider for EE<group urn:xmpp:jingle:apps:grouping:0/>
2022-04-11 04:30:10.459 19984-20332/org.atalk.android D/SMACK: RECV (0):
<iq xml:lang='en' to='swordfish@atalk.sytes.net/atalk' from='parrot@atalk.sytes.net/Conversations.lxYf' type='set' id='uaYdMxlWq-qm'>
<jingle xmlns='urn:xmpp:jingle:1' sid='2rV9iOj12EjXNxEOcOyHiQ' action='transport-info'>
<content name='0' creator='initiator'>
<transport xmlns='urn:xmpp:jingle:transports:ice-udp:1' ufrag='BDNh' pwd='3uLJegIm1j87sIb3G320VK3m'>
<candidate port='60639' foundation='337499441' component='1' priority='2122260223' type='host' generation='0' protocol='udp' ip='192.168.1.37' id='a514de2e-559b-4af2-9144-18c7bc8add79'/>
</transport>
</content>
</jingle>
</iq>
2022-04-11 04:30:10.465 19984-20332/org.atalk.android D/SMACK: RECV (0):
<iq xml:lang='en' to='swordfish@atalk.sytes.net/atalk' from='parrot@atalk.sytes.net/Conversations.lxYf' type='set' id='pMnH3lNqVfZD'>
<jingle xmlns='urn:xmpp:jingle:1' sid='2rV9iOj12EjXNxEOcOyHiQ' action='transport-info'>
<content name='0' creator='initiator'>
<transport xmlns='urn:xmpp:jingle:transports:ice-udp:1' ufrag='BDNh' pwd='3uLJegIm1j87sIb3G320VK3m'>
<candidate port='37753' foundation='337499441' component='2' priority='2122260222' type='host' generation='0' protocol='udp' ip='192.168.1.37' id='37760aab-d6a6-4e87-9ff2-34df6ab13098'/>
</transport>
</content>
</jingle>
</iq>
2022-04-11 04:30:10.475 19984-20332/org.atalk.android D/SMACK: RECV (0):
<iq xml:lang='en' to='swordfish@atalk.sytes.net/atalk' from='parrot@atalk.sytes.net/Conversations.lxYf' type='set' id='AYOqZJazLfxO'>
<jingle xmlns='urn:xmpp:jingle:1' sid='2rV9iOj12EjXNxEOcOyHiQ' action='transport-info'>
<content name='0' creator='initiator'>
<transport xmlns='urn:xmpp:jingle:transports:ice-udp:1' ufrag='BDNh' pwd='3uLJegIm1j87sIb3G320VK3m'>
<candidate rel-port='60639' port='60639' foundation='842163049' component='1' priority='1686052607' type='srflx' generation='0' protocol='udp' ip='42.60.7.13' rel-addr='192.168.1.37' id='94ff92f7-d61a-4549-9994-071750c15dac'/>
</transport>
</content>
</jingle>
</iq>
###=> 2022-04-11 04:30:10.480 19984-20551/org.atalk.android I/aTalk: [329] org.jivesoftware.smackx.jingle_rtp.JingleCallSessionImpl.<init>() Register JingleSession Handler: parrot@atalk.sytes.net/Conversations.lxYf 2rV9iOj12EjXNxEOcOyHiQ
2022-04-11 04:30:10.485 19984-20893/org.atalk.android D/(OperationSetBasicTelephonyJabberImpl.java:700)#processJingleSynchronize: ### Processing Jingle IQ UHoKGByU7SCQ: (session-initiate) synchronized
2022-04-11 04:30:10.485 19984-20332/org.atalk.android D/SMACK: RECV (0):
<iq xml:lang='en' to='swordfish@atalk.sytes.net/atalk' from='parrot@atalk.sytes.net/Conversations.lxYf' type='set' id='I5vMpfctGRjP'>
<jingle xmlns='urn:xmpp:jingle:1' sid='2rV9iOj12EjXNxEOcOyHiQ' action='transport-info'>
<content name='0' creator='initiator'>
<transport xmlns='urn:xmpp:jingle:transports:ice-udp:1' ufrag='BDNh' pwd='3uLJegIm1j87sIb3G320VK3m'>
<candidate rel-port='37753' port='37753' foundation='842163049' component='2' priority='1686052606' type='srflx' generation='0' protocol='udp' ip='42.60.7.13' rel-addr='192.168.1.37' id='20e6059c-cc56-483c-898e-b67828492d38'/>
</transport>
</content>
</jingle>
</iq>
2022-04-11 04:30:10.502 19984-20894/org.atalk.android D/(OperationSetBasicTelephonyJabberImpl.java:700)#processJingleSynchronize: ### Processing Jingle IQ AYOqZJazLfxO: (transport-info) synchronized
2022-04-11 04:30:10.503 19984-20894/org.atalk.android D/(OperationSetBasicTelephonyJabberImpl.java:1033)#processTransportInfo: ### Process session-initiate transport (trailing): AYOqZJazLfxO
2022-04-11 04:30:10.504 19984-20332/org.atalk.android D/SMACK: RECV (0):
<iq xml:lang='en' to='swordfish@atalk.sytes.net/atalk' from='parrot@atalk.sytes.net/Conversations.lxYf' type='set' id='6ZvCZxhwfCvr'>
<jingle xmlns='urn:xmpp:jingle:1' sid='2rV9iOj12EjXNxEOcOyHiQ' action='transport-info'>
<content name='0' creator='initiator'>
<transport xmlns='urn:xmpp:jingle:transports:ice-udp:1' ufrag='BDNh' pwd='3uLJegIm1j87sIb3G320VK3m'>
<candidate rel-port='53762' port='56704' foundation='776666309' component='1' priority='25108479' type='relay' generation='0' protocol='udp' ip='42.60.7.13' rel-addr='42.60.7.13' id='b757ea1a-f6d1-471e-9445-bf0e02a20b30'/>
</transport>
</content>
</jingle>
</iq>
###=> 2022-04-11 04:30:10.510 19984-20550/org.atalk.android W/aTalk: [328] org.jivesoftware.smackx.jingle.JingleManager.handleIQRequest() Unknown session: (uaYdMxlWq-qm) 2rV9iOj12EjXNxEOcOyHiQ
2022-04-11 04:30:10.515 19984-20331/org.atalk.android D/SMACK: SENT (0):
<iq to='parrot@atalk.sytes.net/Conversations.lxYf' id='UHoKGByU7SCQ' type='result'>
</iq>
<iq to='parrot@atalk.sytes.net/Conversations.lxYf' id='AYOqZJazLfxO' type='result'>
</iq>
2022-04-11 04:30:10.520 19984-20332/org.atalk.android D/SMACK: RECV (0):
<iq xml:lang='en' to='swordfish@atalk.sytes.net/atalk' from='parrot@atalk.sytes.net/Conversations.lxYf' type='set' id='J8RuamXkv4VX'>
<jingle xmlns='urn:xmpp:jingle:1' sid='2rV9iOj12EjXNxEOcOyHiQ' action='transport-info'>
<content name='0' creator='initiator'>
<transport xmlns='urn:xmpp:jingle:transports:ice-udp:1' ufrag='BDNh' pwd='3uLJegIm1j87sIb3G320VK3m'>
<candidate rel-port='42487' port='55136' foundation='776666309' component='2' priority='25108478' type='relay' generation='0' protocol='udp' ip='42.60.7.13' rel-addr='42.60.7.13' id='b73c7e64-28f1-45fc-89d3-4ea422ccbe03'/>
</transport>
</content>
</jingle>
</iq>
2022-04-11 04:30:10.529 19984-20897/org.atalk.android D/(OperationSetBasicTelephonyJabberImpl.java:816)#processJingle: ### Processing Jingle IQ (transport-info); callPeer: parrot@atalk.sytes.net/Conversations.lxYf
2022-04-11 04:30:10.529 19984-20897/org.atalk.android D/(OperationSetBasicTelephonyJabberImpl.java:1033)#processTransportInfo: ### Process session-initiate transport (trailing): 6ZvCZxhwfCvr
2022-04-11 04:30:10.534 19984-20896/org.atalk.android D/(OperationSetBasicTelephonyJabberImpl.java:816)#processJingle: ### Processing Jingle IQ (transport-info); callPeer: parrot@atalk.sytes.net/Conversations.lxYf
2022-04-11 04:30:10.535 19984-20896/org.atalk.android D/(OperationSetBasicTelephonyJabberImpl.java:1033)#processTransportInfo: ### Process session-initiate transport (trailing): I5vMpfctGRjP
###=> 2022-04-11 04:30:10.543 19984-20552/org.atalk.android W/aTalk: [330] org.jivesoftware.smackx.jingle.JingleManager.handleIQRequest() Unknown session: (pMnH3lNqVfZD) 2rV9iOj12EjXNxEOcOyHiQ
2022-04-11 04:30:10.549 19984-20898/org.atalk.android D/(OperationSetBasicTelephonyJabberImpl.java:816)#processJingle: ### Processing Jingle IQ (transport-info); callPeer: parrot@atalk.sytes.net/Conversations.lxYf
2022-04-11 04:30:10.550 19984-20898/org.atalk.android D/(OperationSetBasicTelephonyJabberImpl.java:1033)#processTransportInfo: ### Process session-initiate transport (trailing): J8RuamXkv4VX
2022-04-11 04:30:10.561 19984-20331/org.atalk.android D/SMACK: SENT (0):
<iq to='parrot@atalk.sytes.net/Conversations.lxYf' id='uaYdMxlWq-qm' type='error'>
<error type='cancel'>
<item-not-found xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'/>
<unknown-session xmlns='urn:xmpp:jingle:errors:1'/>
</error>
</iq>
<iq to='parrot@atalk.sytes.net/Conversations.lxYf' id='6ZvCZxhwfCvr' type='result'>
</iq>
<iq to='parrot@atalk.sytes.net/Conversations.lxYf' id='I5vMpfctGRjP' type='result'>
</iq>
<iq to='parrot@atalk.sytes.net/Conversations.lxYf' id='pMnH3lNqVfZD' type='error'>
<error type='cancel'>
<item-not-found xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'/>
<unknown-session xmlns='urn:xmpp:jingle:errors:1'/>
</error>
</iq>
<iq to='parrot@atalk.sytes.net/Conversations.lxYf' id='J8RuamXkv4VX' type='result'>
</iq>
2022-04-11 04:30:10.587 19984-20332/org.atalk.android D/SMACK: RECV (0):
<a h='58' xmlns='urn:xmpp:sm:3'/>
2022-04-11 04:30:10.620 19984-20895/org.atalk.android I/aTalk: [382] org.ice4j.ice.Agent.log() Changing agent ICE Agent (stream-count=0 ice-pwd:ppeabb9fc8iirgeohl2nqvf81 ice-ufrag:451ig1g0aimsla tie-breaker:6378687587285616578):
role from controlling = true to controlling = false
2022-04-11 04:30:10.799 19984-20895/org.atalk.android I/(IceUdpTransportManager.java:235)#createIceAgent: Auto discovered STUN/TURN-server harvester is null
2022-04-11 04:30:10.807 19984-20895/org.atalk.android I/(IceUdpTransportManager.java:322)#createIceAgent: End gathering harvesters within 205 ms; size: 3; Harvesters:
[STUN harvester(srvr: 172.217.213.127:19302/udp), net.java.sip.communicator.impl.protocol.jabber.JingleNodesHarvester@cb814a6, UPNPHarvester]
2022-04-11 04:30:10.821 19984-20895/org.atalk.android D/(IceUdpTransportManager.java:742)#createIceStream: Created Ice stream agent for audio
2022-04-11 04:30:10.843 19984-20895/org.atalk.android I/aTalk: [382] org.ice4j.ice.Agent.log() Gathering candidates for component audio.RTP. Local ufrag 451ig1g0aimsla
2022-04-11 04:30:10.861 19984-20895/org.atalk.android I/aTalk: [382] org.ice4j.ice.harvest.HostCandidateHarvester.log() Host candidate added: candidate:1 1 udp 2130706431 fe80::1004:3eff:fe07:ba63 5002 typ host
2022-04-11 04:30:10.880 19984-20895/org.atalk.android I/aTalk: [382] org.ice4j.ice.harvest.HostCandidateHarvester.log() Host candidate added: candidate:2 1 udp 2130706431 192.168.1.167 5002 typ host
2022-04-11 04:30:10.899 19984-20895/org.atalk.android I/aTalk: [382] org.ice4j.ice.harvest.HostCandidateHarvester.log() Host candidate added: candidate:3 1 udp 2113932031 10.170.32.102 5002 typ host
2022-04-11 04:30:10.905 19984-20581/org.atalk.android I/(JingleNodesHarvester.java:71)#harvest: Jingle Nodes harvest start!
2022-04-11 04:30:10.905 19984-20581/org.atalk.android D/(JingleNodesHarvester.java:139)#harvest: Jingle Nodes: []
2022-04-11 04:30:10.920 19984-20579/org.atalk.android I/aTalk: [341] org.ice4j.ice.harvest.UPNPHarvester.log() Begin UPnP harvesting! started: false; device: null
2022-04-11 04:30:11.024 19984-20584/org.atalk.android I/aTalk: [346] org.ice4j.ice.Component.log() Add transport candidate: candidate:4 1 udp 1677724415 42.60.7.13 5002 typ srflx raddr 192.168.1.167 rport 5002;
redundantCandidate: null
2022-04-11 04:30:12.070 19984-20895/org.atalk.android D/(IceUdpTransportManager.java:764)#createIceStream: Updating the port tracker min port: 5003
2022-04-11 04:30:12.095 19984-20331/org.atalk.android D/SMACK: SENT (0):
<iq to='parrot@atalk.sytes.net/Conversations.lxYf' id='3171Z-20' type='set'>
<jingle xmlns='urn:xmpp:jingle:1' initiator='swordfish@atalk.sytes.net/atalk' action='transport-info' sid='2rV9iOj12EjXNxEOcOyHiQ'>
<content creator='initiator' name='0'>
<transport xmlns='urn:xmpp:jingle:transports:ice-udp:1' ufrag='451ig1g0aimsla' pwd='ppeabb9fc8iirgeohl2nqvf81'>
<rtcp-mux/>
<candidate foundation='1' component='1' protocol='udp' priority='2130706431' generation='0' id='9' ip='fe80::1004:3eff:fe07:ba63' port='5002' type='host' network='0'/>
<candidate foundation='2' component='1' protocol='udp' priority='2130706431' generation='0' id='10' ip='192.168.1.167' port='5002' type='host' network='0'/>
<candidate foundation='3' component='1' protocol='udp' priority='2113932031' generation='0' id='11' ip='10.170.32.102' port='5002' type='host' network='0'/>
<candidate foundation='4' component='1' protocol='udp' priority='1677724415' generation='0' id='12' ip='42.60.7.13' port='5002' type='srflx' rel-addr='192.168.1.167' rel-port='5002' network='0'/>
</transport>
</content>
</jingle>
</iq>
2022-04-11 04:30:15.576 19984-20332/org.atalk.android D/SMACK: RECV (0):
<iq xml:lang='en' to='swordfish@atalk.sytes.net/atalk' from='parrot@atalk.sytes.net/Conversations.lxYf' type='error' id='3171Z-20'>
<error type='cancel'>
<item-not-found xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'/>
<unknown-session xmlns='urn:xmpp:jingle:errors:1'/>
</error>
</iq>
2022-04-11 04:30:15.581 19984-20332/org.atalk.android D/SMACK: RECV (0):
<r xmlns='urn:xmpp:sm:3'/>
2022-04-11 04:30:15.585 19984-20895/org.atalk.android I/(CallPeerMediaHandlerJabberImpl.java:938)#harvestCandidates: End candidate harvest within 4764 ms
2022-04-11 04:30:15.585 19984-20331/org.atalk.android D/SMACK: SENT (0):
<a xmlns='urn:xmpp:sm:3' h='74'/>
2022-04-11 04:30:15.600 19984-20895/org.atalk.android I/aTalk: [382] org.ice4j.ice.Component.log() Add remote candidate for audio.RTP: 42.60.7.13:60639/udp/srflx
2022-04-11 04:30:15.602 19984-20895/org.atalk.android W/(IceUdpTransportManager.java:978)#startConnectivityEstablishment: Skip invalid component candidate: <candidate xmlns='urn:xmpp:jingle:transports:ice-udp:1' rel-port='37753' port='37753' foundation='842163049' component='2' priority='1686052606' type='srflx' generation='0' protocol='udp' ip='42.60.7.13' rel-addr='192.168.1.37' id='20e6059c-cc56-483c-898e-b67828492d38'/>
2022-04-11 04:30:15.609 19984-20895/org.atalk.android I/aTalk: [382] org.ice4j.ice.Component.log() Add remote candidate for audio.RTP: 42.60.7.13:56704/udp/relay
2022-04-11 04:30:15.612 19984-20895/org.atalk.android W/(IceUdpTransportManager.java:978)#startConnectivityEstablishment: Skip invalid component candidate: <candidate xmlns='urn:xmpp:jingle:transports:ice-udp:1' rel-port='42487' port='55136' foundation='776666309' component='2' priority='25108478' type='relay' generation='0' protocol='udp' ip='42.60.7.13' rel-addr='42.60.7.13' id='b73c7e64-28f1-45fc-89d3-4ea422ccbe03'/>
2022-04-11 04:30:15.618 19984-20895/org.atalk.android I/aTalk: [382] org.ice4j.ice.Agent.log() Start ICE connectivity establishment. Local ufrag 451ig1g0aimsla
2022-04-11 04:30:15.625 19984-20895/org.atalk.android I/aTalk: [382] org.ice4j.ice.Agent.log() Init checklist for stream audio
2022-04-11 04:30:15.635 19984-20895/org.atalk.android I/aTalk: [382] org.ice4j.ice.Agent.log() ICE state changed from Waiting to Running. Local ufrag 451ig1g0aimsla
2022-04-11 04:30:15.641 19984-20895/org.atalk.android I/aTalk: [382] org.ice4j.ice.ConnectivityCheckClient.log() Start connectivity checks.
2022-04-11 04:30:15.645 19984-20895/org.atalk.android D/(IceUdpTransportManager.java:877)#startConnectivityEstablishment: ### Processed Jingle (transport-info) for media: [audio]; startConnectivityEstablishment: true
2022-04-11 04:30:15.651 19984-20895/org.atalk.android D/(AbstractCallPeer.java:319)#fireCallPeerChangeEvent: Dispatching CallPeerChangeEvent (1): [Call: id=2rV9iOj12EjXNxEOcOyHiQ peers=1]; Events: CallPeerChangeEvent: type=CallPeerStatusChange oldV=net.java.sip.communicator.service.protocol.CallPeerState:Unknown newV=net.java.sip.communicator.service.protocol.CallPeerState:Incoming Call for peer=parrot@atalk.sytes.net <parrot@atalk.sytes.net/Conversations.lxYf>; status=Incoming Call
2022-04-11 04:30:15.652 19984-20895/org.atalk.android D/(AbstractCallPeer.java:335)#fireCallPeerChangeEvent: Dispatching CallPeerChangeEvent CALL_PEER_STATE_CHANGE to: Call: id=2rV9iOj12EjXNxEOcOyHiQ peers=1
2022-04-11 04:30:15.656 19984-20331/org.atalk.android D/SMACK: SENT (0):
<iq to='parrot@atalk.sytes.net/Conversations.lxYf' id='3171Z-21' type='set'>
<jingle xmlns='urn:xmpp:jingle:1' initiator='swordfish@atalk.sytes.net/atalk' action='session-info' sid='2rV9iOj12EjXNxEOcOyHiQ'>
<ringing xmlns='urn:xmpp:jingle:apps:rtp:info:1'/>
</jingle>
</iq>
2022-04-11 04:30:15.659 19984-20895/org.atalk.android D/(AndroidCallListener.java:94)#onCallEvent: Received CallEvent: CallEvent:[id=2 Call=Call: id=2rV9iOj12EjXNxEOcOyHiQ peers=1]: 2rV9iOj12EjXNxEOcOyHiQ
2022-04-11 04:30:15.704 19984-20895/org.atalk.android D/(OperationSetAutoAnswerJabberImpl.java:87)#autoAnswer: OnJingleMessageAccept (auto answer): true
2022-04-11 04:30:15.732 19984-20924/org.atalk.android D/(AbstractCallPeer.java:319)#fireCallPeerChangeEvent: Dispatching CallPeerChangeEvent (4): [Call: id=2rV9iOj12EjXNxEOcOyHiQ peers=1, net.java.sip.communicator.impl.callhistory.CallHistoryServiceImpl$1@f4d124, net.java.sip.communicator.plugin.notificationwiring.NotificationManager@5918f8b, net.java.sip.communicator.service.protocol.media.AbstractOperationSetTelephonyConferencing$1@938a868]; Events: CallPeerChangeEvent: type=CallPeerStatusChange oldV=net.java.sip.communicator.service.protocol.CallPeerState:Incoming Call newV=net.java.sip.communicator.service.protocol.CallPeerState:Connecting* for peer=parrot@atalk.sytes.net <parrot@atalk.sytes.net/Conversations.lxYf>; status=Connecting*
2022-04-11 04:30:15.733 19984-20924/org.atalk.android D/(AbstractCallPeer.java:335)#fireCallPeerChangeEvent: Dispatching CallPeerChangeEvent CALL_PEER_STATE_CHANGE to: Call: id=2rV9iOj12EjXNxEOcOyHiQ peers=1
2022-04-11 04:30:15.733 19984-20924/org.atalk.android D/(AbstractCallPeer.java:335)#fireCallPeerChangeEvent: Dispatching CallPeerChangeEvent CALL_PEER_STATE_CHANGE to: net.java.sip.communicator.impl.callhistory.CallHistoryServiceImpl$1@f4d124
2022-04-11 04:30:15.735 19984-20924/org.atalk.android D/(AbstractCallPeer.java:335)#fireCallPeerChangeEvent: Dispatching CallPeerChangeEvent CALL_PEER_STATE_CHANGE to: net.java.sip.communicator.plugin.notificationwiring.NotificationManager@5918f8b
2022-04-11 04:30:15.735 19984-20924/org.atalk.android D/(NotificationManager.java:1132)#peerStateChanged: Peer State Changed to net.java.sip.communicator.service.protocol.CallPeerState:Connecting*
2022-04-11 04:30:15.740 19984-20924/org.atalk.android D/(AbstractCallPeer.java:335)#fireCallPeerChangeEvent: Dispatching CallPeerChangeEvent CALL_PEER_STATE_CHANGE to: net.java.sip.communicator.service.protocol.media.AbstractOperationSetTelephonyConferencing$1@938a868
2022-04-11 04:30:17.962 19984-20332/org.atalk.android D/SMACK: RECV (0):
<iq xml:lang='en' to='swordfish@atalk.sytes.net/atalk' from='parrot@atalk.sytes.net/Conversations.lxYf' type='error' id='3171Z-21'>
<error type='cancel'>
<item-not-found xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'/>
<unknown-session xmlns='urn:xmpp:jingle:errors:1'/>
</error>
</iq>
2022-04-11 04:30:17.978 19984-20332/org.atalk.android D/SMACK: RECV (0):
<r xmlns='urn:xmpp:sm:3'/>
2022-04-11 04:30:17.982 19984-20331/org.atalk.android D/SMACK: SENT (0):
<a xmlns='urn:xmpp:sm:3' h='75'/>
2022-04-11 04:30:19.019 19984-20930/org.atalk.android I/aTalk: [398] org.ice4j.ice.ConnectivityCheckClient.log() timeout for pair: 192.168.1.167:5002/udp/host -> 42.60.7.13:60639/udp/srflx (audio.RTP), failing.
2022-04-11 04:30:19.029 19984-20585/org.atalk.android I/aTalk: [347] org.ice4j.ice.ConnectivityCheckClient.log() timeout for pair: 10.170.32.102:5002/udp/host -> 42.60.7.13:60639/udp/srflx (audio.RTP), failing.
2022-04-11 04:30:19.038 19984-20930/org.atalk.android I/aTalk: [398] org.ice4j.ice.ConnectivityCheckClient.log() timeout for pair: 192.168.1.167:5002/udp/host -> 42.60.7.13:56704/udp/relay (audio.RTP), failing.
2022-04-11 04:30:19.133 19984-20930/org.atalk.android I/aTalk: [398] org.ice4j.ice.ConnectivityCheckClient.log() timeout for pair: 10.170.32.102:5002/udp/host -> 42.60.7.13:56704/udp/relay (audio.RTP), failing.
2022-04-11 04:30:19.142 19984-20930/org.atalk.android I/aTalk: [398] org.ice4j.ice.ConnectivityCheckClient.log() CheckList will failed in a few seconds if no succeeded checks come
2022-04-11 04:30:23.979 19984-20924/org.atalk.android D/(CallPeerMediaHandler.java:974)#initStream: Initializing audio stream: rtpmap:-1 opus/48000/2 fmtp:useinbandfec=1; peer: parrot@atalk.sytes.net <parrot@atalk.sytes.net/Conversations.lxYf>; status=Connecting*
2022-04-11 04:30:23.988 19984-20924/org.atalk.android I/(MediaHandler.java:821)#registerDynamicPTsWithStream: Dynamic PT map: 126=rtpmap:-1 telephone-event/8000; 111=rtpmap:-1 opus/48000/2 fmtp:useinbandfec=1;minptime=10; 102=rtpmap:-1 iLBC/8000; 103=rtpmap:-1 unknown/90000;
2022-04-11 04:30:23.989 19984-20924/org.atalk.android I/(MediaHandler.java:833)#registerDynamicPTsWithStream: PT overrides [103->113 ]
2022-04-11 04:30:23.991 19984-20924/org.atalk.android D/(AbstractRTPConnector.java:387)#setDirection: setDirection sendrecv
2022-04-11 04:30:24.040 19984-20331/org.atalk.android D/SMACK: SENT (0):
<iq to='parrot@atalk.sytes.net/Conversations.lxYf' id='3171Z-22' type='set'>
<jingle xmlns='urn:xmpp:jingle:1' responder='swordfish@atalk.sytes.net/atalk' action='session-accept' sid='2rV9iOj12EjXNxEOcOyHiQ'>
<content creator='initiator' name='0'>
<description xmlns='urn:xmpp:jingle:apps:rtp:1' media='audio' ssrc='735582216'>
<payload-type id='111' name='opus' channels='2' clockrate='48000'>
<parameter name='useinbandfec' value='1'/>
<parameter name='ptime' value='20'/>
</payload-type>
<payload-type id='102' name='iLBC' channels='1' clockrate='8000'/>
<payload-type id='0' name='PCMU' channels='1' clockrate='8000'/>
<payload-type id='8' name='PCMA' channels='1' clockrate='8000'/>
<payload-type id='126' name='telephone-event' channels='1' clockrate='8000'/>
<rtp-hdrext xmlns='urn:xmpp:jingle:apps:rtp:rtp-hdrext:0' uri='urn:ietf:params:rtp-hdrext:ssrc-audio-level' senders='both' id='1'>
<parameter name='attributes'/>
</rtp-hdrext>
<rtcp-mux/>
<source xmlns='urn:xmpp:jingle:apps:rtp:ssma:0' ssrc='735582216'>
<parameter name='cname' value='3f8ad781-383c-4a57-9b8a-782bdf9ef6d1'/>
<parameter name='msid' value='889bd7ac-67a3-41c4-86c7-0226511d2664 audio11296557'/>
<parameter name='mslabel' value='889bd7ac-67a3-41c4-86c7-0226511d2664'/>
<parameter name='label' value='audio11296557'/>
</source>
</description>
<inputevt xmlns='http://jitsi.org/protocol/inputevt'/>
<transport xmlns='urn:xmpp:jingle:transports:ice-udp:1' ufrag='451ig1g0aimsla' pwd='ppeabb9fc8iirgeohl2nqvf81'>
<fingerprint xmlns='urn:xmpp:jingle:apps:dtls:0' hash='sha-256' setup='active'>
2B:6B:91:78:27:A2:6D:C5:6E:A5:BA:A9:74:05:61:7C:9A:B1:DC:6D:56:CF:FB:B8:45:EA:05:41:DE:85:A5:66
</fingerprint>
</transport>
</content>
<group xmlns='urn:xmpp:jingle:apps:grouping:0' semantics='BUNDLE'>
<content xmlns='urn:xmpp:jingle:1' name='0'/>
</group>
</jingle>
</iq>
<r xmlns='urn:xmpp:sm:3'/>
2022-04-11 04:30:24.152 19984-20920/org.atalk.android I/aTalk: [394] org.ice4j.ice.ConnectivityCheckClient.log() CheckList for stream audio FAILED
2022-04-11 04:30:24.160 19984-20920/org.atalk.android I/aTalk: [394] org.ice4j.ice.Agent.log() ICE state is FAILED
2022-04-11 04:30:24.168 19984-20920/org.atalk.android I/aTalk: [394] org.ice4j.ice.Agent.log() ICE state changed from Running to Failed. Local ufrag 451ig1g0aimsla
2022-04-11 04:30:24.169 19984-20920/org.atalk.android D/(IceUdpTransportManager.java:1039)#propertyChange: Current IceProcessingState: Failed
2022-04-11 04:30:24.176 19984-20924/org.atalk.android I/(CallPeerJabberImpl.java:236)#answer: Failed to establish a connection
net.java.sip.communicator.service.protocol.OperationFailedException: Could not establish connection (ICE failed and no relay found)
at net.java.sip.communicator.impl.protocol.jabber.IceUdpTransportManager.wrapupConnectivityEstablishment(IceUdpTransportManager.java:1080)
at net.java.sip.communicator.impl.protocol.jabber.CallPeerMediaHandlerJabberImpl.wrapupConnectivityEstablishment(CallPeerMediaHandlerJabberImpl.java:1681)
at net.java.sip.communicator.impl.protocol.jabber.CallPeerMediaHandlerJabberImpl.start(CallPeerMediaHandlerJabberImpl.java:1644)
at net.java.sip.communicator.impl.protocol.jabber.CallPeerJabberImpl.answer(CallPeerJabberImpl.java:233)
at net.java.sip.communicator.impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.answerCallPeer(OperationSetBasicTelephonyJabberImpl.java:637)
at net.java.sip.communicator.service.protocol.AbstractOperationSetBasicAutoAnswer$AutoAnswerThread.run(AbstractOperationSetBasicAutoAnswer.java:220)
at java.lang.Thread.run(Thread.java:920)
2022-04-11 04:30:24.263 19984-20924/org.atalk.android I/aTalk: [396] org.ice4j.ice.ComponentSocket.log() Closing.
2022-04-11 04:30:24.266 19984-20924/org.atalk.android D/(AbstractCallPeer.java:319)#fireCallPeerChangeEvent: Dispatching CallPeerChangeEvent (5): [Call: id=2rV9iOj12EjXNxEOcOyHiQ peers=1, net.java.sip.communicator.impl.callhistory.CallHistoryServiceImpl$1@f4d124, net.java.sip.communicator.plugin.notificationwiring.NotificationManager@5918f8b, net.java.sip.communicator.service.protocol.media.AbstractOperationSetTelephonyConferencing$1@938a868, net.java.sip.communicator.util.call.CallPeerAdapter@9c6153f]; Events: CallPeerChangeEvent: type=CallPeerStatusChange oldV=net.java.sip.communicator.service.protocol.CallPeerState:Connecting* newV=net.java.sip.communicator.service.protocol.CallPeerState:Failed for peer=parrot@atalk.sytes.net <parrot@atalk.sytes.net/Conversations.lxYf>; status=Failed
2022-04-11 04:30:24.266 19984-20924/org.atalk.android D/(AbstractCallPeer.java:335)#fireCallPeerChangeEvent: Dispatching CallPeerChangeEvent CALL_PEER_STATE_CHANGE to: Call: id=2rV9iOj12EjXNxEOcOyHiQ peers=1
2022-04-11 04:30:24.267 19984-20924/org.atalk.android D/(Call.java:225)#fireCallPeerEvent: Dispatching CallPeer event to 8 listeners. The event is: CallPeerEvent: ID=2 source peer=parrot@atalk.sytes.net <parrot@atalk.sytes.net/Conversations.lxYf>; status=Failed source call=Call: id=2rV9iOj12EjXNxEOcOyHiQ peers=0
2022-04-11 04:30:24.277 19984-20924/org.atalk.android D/(Call.java:282)#fireCallChangeEvent: Dispatching CallChangeEvent to (8) listeners. CallChangeEvent: type=CallState oldV=net.java.sip.communicator.service.protocol.CallState:Initializing newV=net.java.sip.communicator.service.protocol.CallState:Ended
2022-04-11 04:30:24.280 19984-20924/org.atalk.android D/(AndroidCallListener.java:94)#onCallEvent: Received CallEvent: CallEvent:[id=3 Call=Call: id=2rV9iOj12EjXNxEOcOyHiQ peers=0]: 2rV9iOj12EjXNxEOcOyHiQ
2022-04-11 04:30:24.295 19984-20908/org.atalk.android I/aTalk: [387] org.ice4j.ice.ComponentSocket.log() Failed to receive: java.net.SocketException: Socket closed
2022-04-11 04:30:24.298 19984-20910/org.atalk.android I/aTalk: [389] org.ice4j.ice.ComponentSocket.log() Failed to receive: java.net.SocketException: Socket closed
2022-04-11 04:30:24.329 19984-20912/org.atalk.android I/aTalk: [391] org.ice4j.ice.ComponentSocket.log() Failed to receive: java.net.SocketException: Socket closed
2022-04-11 04:30:24.351 19984-20924/org.atalk.android D/(AbstractCallPeer.java:335)#fireCallPeerChangeEvent: Dispatching CallPeerChangeEvent CALL_PEER_STATE_CHANGE to: net.java.sip.communicator.impl.callhistory.CallHistoryServiceImpl$1@f4d124
2022-04-11 04:30:24.351 19984-20924/org.atalk.android D/(AbstractCallPeer.java:335)#fireCallPeerChangeEvent: Dispatching CallPeerChangeEvent CALL_PEER_STATE_CHANGE to: net.java.sip.communicator.plugin.notificationwiring.NotificationManager@5918f8b
2022-04-11 04:30:24.352 19984-20924/org.atalk.android D/(NotificationManager.java:1132)#peerStateChanged: Peer State Changed to net.java.sip.communicator.service.protocol.CallPeerState:Failed
2022-04-11 04:30:24.352 19984-20924/org.atalk.android D/(AbstractCallPeer.java:335)#fireCallPeerChangeEvent: Dispatching CallPeerChangeEvent CALL_PEER_STATE_CHANGE to: net.java.sip.communicator.service.protocol.media.AbstractOperationSetTelephonyConferencing$1@938a868
2022-04-11 04:30:24.352 19984-20924/org.atalk.android D/(AbstractCallPeer.java:335)#fireCallPeerChangeEvent: Dispatching CallPeerChangeEvent CALL_PEER_STATE_CHANGE to: net.java.sip.communicator.util.call.CallPeerAdapter@9c6153f
2022-04-11 04:30:24.353 19984-20924/org.atalk.android I/(VideoCallActivity.java:685)#setErrorReason: End call reason: Error: Could not establish connection (ICE failed and no relay found)
2022-04-11 04:30:24.354 19984-20924/org.atalk.android D/(CallPeerMediaHandler.java:419)#closeStream: Closing audio stream for parrot@atalk.sytes.net/Conversations.lxYf <parrot@atalk.sytes.net/Conversations.lxYf>; status=Failed
2022-04-11 04:30:24.357 19984-20924/org.atalk.android D/(CallPeerMediaHandler.java:419)#closeStream: Closing video stream for parrot@atalk.sytes.net/Conversations.lxYf <parrot@atalk.sytes.net/Conversations.lxYf>; status=Failed
2022-04-11 04:30:24.362 19984-20331/org.atalk.android D/SMACK: SENT (0):
<iq to='parrot@atalk.sytes.net/Conversations.lxYf' id='3171Z-23' type='set'>
<jingle xmlns='urn:xmpp:jingle:1' action='session-terminate' sid='2rV9iOj12EjXNxEOcOyHiQ'>
<reason>
<general-error/>
<text>
Error: Could not establish connection (ICE failed and no relay found)
</text>
</reason>
</jingle>
</iq>
2022-04-11 04:30:24.366 19984-20924/org.atalk.android I/aTalk: [396] org.jivesoftware.smackx.jingle_rtp.JingleCallSessionImpl.unregisterJingleSessionHandler() Unregister JingleSession Handler: parrot@atalk.sytes.net/Conversations.lxYf 2rV9iOj12EjXNxEOcOyHiQ
2022-04-11 04:30:24.955 19984-20332/org.atalk.android D/SMACK: RECV (0):
<iq xml:lang='en' to='swordfish@atalk.sytes.net/atalk' from='parrot@atalk.sytes.net/Conversations.lxYf' type='error' id='3171Z-22'>
<error type='cancel'>
<item-not-found xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'/>
<unknown-session xmlns='urn:xmpp:jingle:errors:1'/>
</error>
</iq>
2022-04-11 04:30:24.970 19984-20332/org.atalk.android D/SMACK: RECV (0):
<iq xml:lang='en' to='swordfish@atalk.sytes.net/atalk' from='parrot@atalk.sytes.net/Conversations.lxYf' type='error' id='3171Z-23'>
<error type='cancel'>
<item-not-found xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'/>
<unknown-session xmlns='urn:xmpp:jingle:errors:1'/>
</error>
</iq>
2022-04-11 04:33:15.758 19984-20331/org.atalk.android D/SMACK: SENT (0):
<iq to='atalk.sytes.net' id='3171Z-24' type='get'>
<ping xmlns='urn:xmpp:ping'/>
</iq>