[jitsi-dev] Jitsi SIP extension unavailable


#1

Hi,

At times an Asterisk server running in a LAN can't connect/dial a local SIP extension (Jitsi).

When that happens I can see this in Asterisk log:

app_dial.c: Unable to create channel of type 'SIP' (cause 20 - Unknown)

If I'm not mistaken it should be due to the SIP client unregistering or losing connection.
The Jitsi user doesn't report any client messages regarding "network connectivity" (Jitsi usually notifies the user when there's a network problem) but I can't be 100% sure that's true.

Of course the SIP extension was correctly registered before this message appeared in the log (even though I did not have the chance to run 'sip show peer').

However, right after that "unable to create channel" message I can see:

logger.c: -- Unregistered SIP '6019'
logger.c: -- Registered SIP '6019'

From that point on calls seem to establish fine.

(I'm supposing that the Jitsi user actually selected "Offline" on his client and then "Online" again)

The PC Jitsi was running on didn't have any NIC issues during this time lapse.

It's not easy to reproduce this problem

What do you suggest I try?

I also took a look at the Jitsi log file and saw:

10:35:28.691 SEVERE: [80] impl.protocol.sip.SipLogger.logError().122 Error from the JAIN-SIP stack: Cannot find listening point for transport UDP
10:35:28.691 SEVERE: [80] impl.protocol.sip.SipMessageFactory.throwOperationFailedException().2400 Failed to create SUBSCRIBE request.
javax.sip.SipException: Cannot find listening point for transport UDP
  at gov.nist.javax.sip.stack.SIPDialog.createRequest(SIPDialog.java:2300)
  at gov.nist.javax.sip.stack.SIPDialog.createRequest(SIPDialog.java:2231)
  at net.java.sip.communicator.impl.protocol.sip.SipMessageFactory.createRequest(SipMessageFactory.java:681)
  at net.java.sip.communicator.impl.protocol.sip.EventPackageSubscriber.createSubscription(EventPackageSubscriber.java:124)
  at net.java.sip.communicator.impl.protocol.sip.EventPackageSubscriber.access$100(EventPackageSubscriber.java:29)
  at net.java.sip.communicator.impl.protocol.sip.EventPackageSubscriber$SubscriptionRefreshTask.run(EventPackageSubscriber.java:1299)
  at java.util.TimerThread.mainLoop(Unknown Source)
  at java.util.TimerThread.run(Unknown Source)
10:35:28.691 SEVERE: [80] impl.protocol.sip.EventPackageSubscriber.run().1307 Failed to create subscriptionTransaction.
net.java.sip.communicator.service.protocol.OperationFailedException: Failed to create SUBSCRIBE request.
  at net.java.sip.communicator.impl.protocol.sip.ProtocolProviderServiceSipImpl.throwOperationFailedException(ProtocolProviderServiceSipImpl.java:2405)
  at net.java.sip.communicator.impl.protocol.sip.SipMessageFactory.createRequest(SipMessageFactory.java:685)
  at net.java.sip.communicator.impl.protocol.sip.EventPackageSubscriber.createSubscription(EventPackageSubscriber.java:124)
  at net.java.sip.communicator.impl.protocol.sip.EventPackageSubscriber.access$100(EventPackageSubscriber.java:29)
  at net.java.sip.communicator.impl.protocol.sip.EventPackageSubscriber$SubscriptionRefreshTask.run(EventPackageSubscriber.java:1299)
  at java.util.TimerThread.mainLoop(Unknown Source)
  at java.util.TimerThread.run(Unknown Source)
Caused by: javax.sip.SipException: Cannot find listening point for transport UDP
  at gov.nist.javax.sip.stack.SIPDialog.createRequest(SIPDialog.java:2300)
  at gov.nist.javax.sip.stack.SIPDialog.createRequest(SIPDialog.java:2231)
  at net.java.sip.communicator.impl.protocol.sip.SipMessageFactory.createRequest(SipMessageFactory.java:681)
  ... 5 more

I also noticed a big "time gap" in the Jitsi log (but the app was up and running and I'm supposing that at 10:03 is when the user manually selected "Offline" and then "Online" again in order to force re-registration because people were telling him that they tried to call but couldn't connect):

07:38:26.313 INFO: [44] plugin.simpleaccreg.SimpleAccountRegistrationActivator.init().110 SIMPLE ACCOUNT REGISTRATION ...[STARTED]
07:38:26.811 WARNING: [62] service.resources.AbstractResourcesService.getSettingsInt().581 Missing resource for key: net.java.sip.communicator.SIP_PREFERRED_CLEAR_PORT
07:38:26.998 WARNING: [62] service.resources.AbstractResourcesService.getSettingsInt().581 Missing resource for key: net.java.sip.communicator.SIP_PREFERRED_SECURE_PORT
07:38:27.232 INFO: [44] impl.gui.main.account.AccountRegWizardContainerImpl.serviceChanged().313 Handling registration of a new Account Wizard.
07:38:34.397 SEVERE: [63] impl.protocol.jabber.ProtocolProviderServiceJabberImpl.connectUsingSRVRecords().886 No SRV addresses found for _xmpp-client._tcp.jabber.mydomain.org
07:38:35.285 INFO: [63] impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.registrationStateChanged().116 Jingle : ON
07:38:35.971 INFO: [95] impl.protocol.jabber.JingleNodesServiceDiscovery.run().95 Start Jingle Nodes discovery!
07:38:35.971 INFO: [95] impl.protocol.jabber.JingleNodesServiceDiscovery.run().128 Jingle Nodes discovery terminated!
07:38:35.971 INFO: [95] impl.protocol.jabber.JingleNodesServiceDiscovery.run().129 Found 0 Jingle Nodes relay for account: myuser@jabber.mydomain.org in 0 ms.
10:03:32.495 INFO: [158] impl.protocol.sip.SipLogger.logInfo().185 Info from the JAIN-SIP stack: the sip stack timer gov.nist.javax.sip.stack.timers.DefaultSipTimer has been stopped
10:03:32.683 INFO: [44] impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.registrationStateChanged().123 Jingle : OFF
10:03:33.495 INFO: [158] impl.protocol.sip.SipLogger.logInfo().185 Info from the JAIN-SIP stack: the sip stack timer gov.nist.javax.sip.stack.timers.DefaultSipTimer has been stopped
10:03:34.495 WARNING: [160] service.resources.AbstractResourcesService.getSettingsInt().581 Missing resource for key: net.java.sip.communicator.SIP_PREFERRED_CLEAR_PORT
10:03:34.495 INFO: [160] impl.protocol.sip.SipLogger.logInfo().185 Info from the JAIN-SIP stack: the sip stack timer gov.nist.javax.sip.stack.timers.DefaultSipTimer has been started
10:03:34.511 WARNING: [160] service.resources.AbstractResourcesService.getSettingsInt().581 Missing resource for key: net.java.sip.communicator.SIP_PREFERRED_SECURE_PORT
10:03:45.855 SEVERE: [161] impl.protocol.jabber.ProtocolProviderServiceJabberImpl.connectUsingSRVRecords().886 No SRV addresses found for _xmpp-client._tcp.jabber.mydomain.org
10:03:46.214 INFO: [161] impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.registrationStateChanged().116 Jingle : ON
10:03:46.480 INFO: [190] impl.protocol.jabber.JingleNodesServiceDiscovery.run().95 Start Jingle Nodes discovery!
10:03:46.480 INFO: [190] impl.protocol.jabber.JingleNodesServiceDiscovery.run().128 Jingle Nodes discovery terminated!
10:03:46.480 INFO: [190] impl.protocol.jabber.JingleNodesServiceDiscovery.run().129 Found 0 Jingle Nodes relay for account: myuser@jabber.mydomain.org in 16 ms.
10:04:44.589 INFO: [214] impl.protocol.sip.SipLogger.logInfo().185 Info from the JAIN-SIP stack: the sip stack timer gov.nist.javax.sip.stack.timers.DefaultSipTimer has been stopped
10:04:44.761 INFO: [44] impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.registrationStateChanged().123 Jingle : OFF
10:04:45.589 INFO: [214] impl.protocol.sip.SipLogger.logInfo().185 Info from the JAIN-SIP stack: the sip stack timer gov.nist.javax.sip.stack.timers.DefaultSipTimer has been stopped
10:04:46.823 WARNING: [216] service.resources.AbstractResourcesService.getSettingsInt().581 Missing resource for key: net.java.sip.communicator.SIP_PREFERRED_CLEAR_PORT
10:04:46.823 INFO: [216] impl.protocol.sip.SipLogger.logInfo().185 Info from the JAIN-SIP stack: the sip stack timer gov.nist.javax.sip.stack.timers.DefaultSipTimer has been started
10:04:46.839 WARNING: [216] service.resources.AbstractResourcesService.getSettingsInt().581 Missing resource for key: net.java.sip.communicator.SIP_PREFERRED_SECURE_PORT
10:04:53.620 SEVERE: [224] impl.protocol.jabber.ProtocolProviderServiceJabberImpl.connectUsingSRVRecords().886 No SRV addresses found for _xmpp-client._tcp.jabber.mydomain.org
10:04:53.995 INFO: [224] impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.registrationStateChanged().116 Jingle : ON
10:04:54.245 INFO: [246] impl.protocol.jabber.JingleNodesServiceDiscovery.run().95 Start Jingle Nodes discovery!
10:04:54.245 INFO: [246] impl.protocol.jabber.JingleNodesServiceDiscovery.run().128 Jingle Nodes discovery terminated!
10:04:54.245 INFO: [246] impl.protocol.jabber.JingleNodesServiceDiscovery.run().129 Found 0 Jingle Nodes relay for account: myuser@jabber.mydomain.org in 0 ms.
10:06:33.026 INFO: [317] impl.protocol.sip.OperationSetBasicTelephonySipImpl.createOutgoingCall().170 Creating outgoing call to sip:7021@10.215.147.115
10:06:33.026 INFO: [317] util.NetworkUtils.tryRange().123 Ignoring invalid port range [null to null]
10:06:33.026 INFO: [317] util.NetworkUtils.createTracker().213 Ignoring invalid port range [null to null]
10:06:33.026 INFO: [317] util.NetworkUtils.createTracker().213 Ignoring invalid port range [null to null]
10:06:33.026 INFO: [317] util.NetworkUtils.createTracker().213 Ignoring invalid port range [null to null]
10:06:33.057 INFO: [317] util.NetworkUtils.tryRange().123 Ignoring invalid port range [null to null]
10:06:33.057 INFO: [317] util.NetworkUtils.createTracker().213 Ignoring invalid port range [null to null]
10:06:33.057 INFO: [317] util.NetworkUtils.createTracker().213 Ignoring invalid port range [null to null]
10:06:33.057 INFO: [317] util.NetworkUtils.createTracker().213 Ignoring invalid port range [null to null]

Thanks,

Vieri