[jitsi-dev] Auto and manual reconnect failures


#1

I've been observing a failure to reconnect my accounts after reopening
the lid of my laptop with recent revisions of Jitsi. All my accounts
have gone offline upon closing the lid and they do not reconnect after
opening it regardless of whether I manually try to set their status or
the global status to Online/Available. The following is from my log:

20:50:17.134 WARNING:
impl.resources.ResourceManagementServiceImpl.getSettingsInt().754
Missing resource for key:
net.java.sip.communicator.SIP_PREFERRED_CLEAR_PORT
20:50:17.140 INFO: 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
20:50:17.145 WARNING:
impl.resources.ResourceManagementServiceImpl.getSettingsInt().754
Missing resource for key:
net.java.sip.communicator.SIP_PREFERRED_SECURE_PORT
20:50:17.153 SEVERE:
impl.protocol.jabber.ProtocolProviderServiceJabberImpl.connectAndLogin().717
No server addresses found
20:50:17.157 SEVERE:
impl.protocol.sip.ProtocolProviderServiceSipImpl.register().310 No
address found for ProtocolProviderServiceSipImpl(a@ippi.fr (ippi))
20:50:17.159 SEVERE:
impl.protocol.sip.ProtocolProviderServiceSipImpl.register().310 No
address found for ProtocolProviderServiceSipImpl(a@b.u-strasbg.fr
(SIP))
20:50:17.167 INFO: 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
20:50:18.170 INFO: 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
20:55:17.153 INFO:
plugin.reconnectplugin.ReconnectPluginActivator.run().880 Start
reconnecting a@sip-communicator.org (Google Talk)
20:55:17.155 SEVERE:
impl.protocol.jabber.ProtocolProviderServiceJabberImpl.connectAndLogin().717
No server addresses found
20:55:17.160 INFO:
plugin.reconnectplugin.ReconnectPluginActivator.run().880 Start
reconnecting a@ippi.fr (ippi)
20:55:17.160 WARNING:
impl.resources.ResourceManagementServiceImpl.getSettingsInt().754
Missing resource for key:
net.java.sip.communicator.SIP_PREFERRED_CLEAR_PORT
20:55:17.161 INFO: 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
20:55:17.164 WARNING:
impl.resources.ResourceManagementServiceImpl.getSettingsInt().754
Missing resource for key:
net.java.sip.communicator.SIP_PREFERRED_SECURE_PORT
20:55:17.165 INFO:
plugin.reconnectplugin.ReconnectPluginActivator.run().880 Start
reconnecting a@b.u-strasbg.fr (SIP)
20:55:17.172 SEVERE:
impl.protocol.sip.ProtocolProviderServiceSipImpl.register().310 No
address found for ProtocolProviderServiceSipImpl(a@ippi.fr (ippi))
20:55:17.174 SEVERE:
impl.protocol.sip.ProtocolProviderServiceSipImpl.register().310 No
address found for ProtocolProviderServiceSipImpl(a@b.u-strasbg.fr
(SIP))
20:55:17.182 INFO: 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
20:55:18.184 INFO: 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
20:57:01.357 SEVERE:
impl.protocol.jabber.ProtocolProviderServiceJabberImpl.connectAndLogin().717
No server addresses found
20:57:08.008 WARNING:
impl.resources.ResourceManagementServiceImpl.getSettingsInt().754
Missing resource for key:
net.java.sip.communicator.SIP_PREFERRED_CLEAR_PORT
20:57:08.009 INFO: 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
20:57:08.010 WARNING:
impl.resources.ResourceManagementServiceImpl.getSettingsInt().754
Missing resource for key:
net.java.sip.communicator.SIP_PREFERRED_SECURE_PORT
20:57:08.022 SEVERE:
impl.protocol.sip.ProtocolProviderServiceSipImpl.register().310 No
address found for ProtocolProviderServiceSipImpl(a@b.u-strasbg.fr
(SIP))
20:57:08.026 INFO: 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
20:57:09.029 INFO: 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
20:57:12.078 WARNING:
impl.resources.ResourceManagementServiceImpl.getSettingsInt().754
Missing resource for key:
net.java.sip.communicator.SIP_PREFERRED_CLEAR_PORT
20:57:12.079 INFO: 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
20:57:12.081 WARNING:
impl.resources.ResourceManagementServiceImpl.getSettingsInt().754
Missing resource for key:
net.java.sip.communicator.SIP_PREFERRED_SECURE_PORT
20:57:12.092 SEVERE:
impl.protocol.sip.ProtocolProviderServiceSipImpl.register().310 No
address found for ProtocolProviderServiceSipImpl(a@ippi.fr (ippi))
20:57:12.096 INFO: 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
20:57:13.099 INFO: 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

Of course, restarting Jitsi does connect my accounts.


#2

I've been observing a failure to reconnect my accounts after reopening
the lid of my laptop with recent revisions of Jitsi. All my accounts
have gone offline upon closing the lid and they do not reconnect after
opening it regardless of whether I manually try to set their status or
the global status to Online/Available. The following is from my log:

[...]
No server addresses found
[...]

Of course, restarting Jitsi does connect my accounts.

Has the network changed between starting Jitsi the first time and getting
the laptop out of sleep (so that the system got other DNS servers from
DHCP)?

Ingo


#3

Hello, Ingo!

···

On 04.02.2013, at 21:14, "Ingo Bauersachs" <ingo@jitsi.org> wrote:

[...]
No server addresses found
[...]

Of course, restarting Jitsi does connect my accounts.

Has the network changed between starting Jitsi the first time and getting
the laptop out of sleep (so that the system got other DNS servers from
DHCP)?

I guess the network didn't change because I didn't move my laptop at all and the only network available to it was always my home wi-fi. Before I noticed the accounts had not automatically reconnected, I browsed a few pages in my browser and I received a couple of new e-mails.

Best regards,
Lyubomir


#4

This is also a big issue when traveling and using GPRS/UMTS.
With this there are quite often connection losses inbetween.
Jitsi does not automatically reconnect. Either chat windows
become stale and have to closed and reopened or it only
helps taking the account off and online again after having
a new network connection. In this case it is not very
resilient.

Cheers,
Matt

···

Am 04.02.2013 20:06, schrieb Lyubomir Marinov:

I've been observing a failure to reconnect my accounts after reopening
the lid of my laptop with recent revisions of Jitsi. All my accounts
have gone offline upon closing the lid and they do not reconnect after
opening it regardless of whether I manually try to set their status or
the global status to Online/Available. The following is from my log:

20:50:17.134 WARNING:
impl.resources.ResourceManagementServiceImpl.getSettingsInt().754
Missing resource for key:
net.java.sip.communicator.SIP_PREFERRED_CLEAR_PORT
20:50:17.140 INFO: 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
20:50:17.145 WARNING:
impl.resources.ResourceManagementServiceImpl.getSettingsInt().754
Missing resource for key:
net.java.sip.communicator.SIP_PREFERRED_SECURE_PORT
20:50:17.153 SEVERE:
impl.protocol.jabber.ProtocolProviderServiceJabberImpl.connectAndLogin().717
No server addresses found
20:50:17.157 SEVERE:
impl.protocol.sip.ProtocolProviderServiceSipImpl.register().310 No
address found for ProtocolProviderServiceSipImpl(a@ippi.fr (ippi))
20:50:17.159 SEVERE:
impl.protocol.sip.ProtocolProviderServiceSipImpl.register().310 No
address found for ProtocolProviderServiceSipImpl(a@b.u-strasbg.fr
(SIP))
20:50:17.167 INFO: 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
20:50:18.170 INFO: 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
20:55:17.153 INFO:
plugin.reconnectplugin.ReconnectPluginActivator.run().880 Start
reconnecting a@sip-communicator.org (Google Talk)
20:55:17.155 SEVERE:
impl.protocol.jabber.ProtocolProviderServiceJabberImpl.connectAndLogin().717
No server addresses found
20:55:17.160 INFO:
plugin.reconnectplugin.ReconnectPluginActivator.run().880 Start
reconnecting a@ippi.fr (ippi)
20:55:17.160 WARNING:
impl.resources.ResourceManagementServiceImpl.getSettingsInt().754
Missing resource for key:
net.java.sip.communicator.SIP_PREFERRED_CLEAR_PORT
20:55:17.161 INFO: 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
20:55:17.164 WARNING:
impl.resources.ResourceManagementServiceImpl.getSettingsInt().754
Missing resource for key:
net.java.sip.communicator.SIP_PREFERRED_SECURE_PORT
20:55:17.165 INFO:
plugin.reconnectplugin.ReconnectPluginActivator.run().880 Start
reconnecting a@b.u-strasbg.fr (SIP)
20:55:17.172 SEVERE:
impl.protocol.sip.ProtocolProviderServiceSipImpl.register().310 No
address found for ProtocolProviderServiceSipImpl(a@ippi.fr (ippi))
20:55:17.174 SEVERE:
impl.protocol.sip.ProtocolProviderServiceSipImpl.register().310 No
address found for ProtocolProviderServiceSipImpl(a@b.u-strasbg.fr
(SIP))
20:55:17.182 INFO: 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
20:55:18.184 INFO: 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
20:57:01.357 SEVERE:
impl.protocol.jabber.ProtocolProviderServiceJabberImpl.connectAndLogin().717
No server addresses found
20:57:08.008 WARNING:
impl.resources.ResourceManagementServiceImpl.getSettingsInt().754
Missing resource for key:
net.java.sip.communicator.SIP_PREFERRED_CLEAR_PORT
20:57:08.009 INFO: 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
20:57:08.010 WARNING:
impl.resources.ResourceManagementServiceImpl.getSettingsInt().754
Missing resource for key:
net.java.sip.communicator.SIP_PREFERRED_SECURE_PORT
20:57:08.022 SEVERE:
impl.protocol.sip.ProtocolProviderServiceSipImpl.register().310 No
address found for ProtocolProviderServiceSipImpl(a@b.u-strasbg.fr
(SIP))
20:57:08.026 INFO: 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
20:57:09.029 INFO: 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
20:57:12.078 WARNING:
impl.resources.ResourceManagementServiceImpl.getSettingsInt().754
Missing resource for key:
net.java.sip.communicator.SIP_PREFERRED_CLEAR_PORT
20:57:12.079 INFO: 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
20:57:12.081 WARNING:
impl.resources.ResourceManagementServiceImpl.getSettingsInt().754
Missing resource for key:
net.java.sip.communicator.SIP_PREFERRED_SECURE_PORT
20:57:12.092 SEVERE:
impl.protocol.sip.ProtocolProviderServiceSipImpl.register().310 No
address found for ProtocolProviderServiceSipImpl(a@ippi.fr (ippi))
20:57:12.096 INFO: 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
20:57:13.099 INFO: 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

Of course, restarting Jitsi does connect my accounts.


#5

[...]
No server addresses found
[...]

Of course, restarting Jitsi does connect my accounts.

Has the network changed between starting Jitsi the first time and getting
the laptop out of sleep (so that the system got other DNS servers from
DHCP)?

I guess the network didn't change because I didn't move my laptop at all

and

the only network available to it was always my home wi-fi. Before I

noticed

the accounts had not automatically reconnected, I browsed a few pages in

my

browser and I received a couple of new e-mails.

I've just committed a change in the ParallelResolver. If that doesn't help,
could you please send me:
- the complete log
- the systems current DNS servers (as assigned from DHCP)
- a Wireshark trace (during the failing connect phase to see where the DNS
queries are really going)
- the results of a manual SRV nslookup to
_xmpp-client._tcp.sip-communicator.org.

Best regards,
Lyubomir

Regards,
Ingo


#6

Could anyone maybe also take a look at another reconnect bug, that I
submitted around two weeks ago?
http://permalink.gmane.org/gmane.comp.voip.sip-communicator.devel/14480

Regards,
Alexander

···

2013/2/4 Lyubomir Marinov <lyubomir.marinov@jitsi.org>

Hello, Ingo!

On 04.02.2013, at 21:14, "Ingo Bauersachs" <ingo@jitsi.org> wrote:
>> [...]
>> No server addresses found
>> [...]
>>
>> Of course, restarting Jitsi does connect my accounts.
>
> Has the network changed between starting Jitsi the first time and getting
> the laptop out of sleep (so that the system got other DNS servers from
> DHCP)?

I guess the network didn't change because I didn't move my laptop at all
and the only network available to it was always my home wi-fi. Before I
noticed the accounts had not automatically reconnected, I browsed a few
pages in my browser and I received a couple of new e-mails.

Best regards,
Lyubomir


#7

I noticed this as well on OS X 10.8.2.

Jitsi used to auto-reconnect when the computer was put into sleep mode and then was woke up again. Now jitsi stays disconnected, despite the computer being wake. I can manually set the accounts to "online". But in previous builds this was not neccessary.

Best, steve

···

Am 04.02.2013 um 20:25 schrieb Lyubomir Marinov <lyubomir.marinov@jitsi.org>:

Hello, Ingo!

On 04.02.2013, at 21:14, "Ingo Bauersachs" <ingo@jitsi.org> wrote:

[...]
No server addresses found
[...]

Of course, restarting Jitsi does connect my accounts.

Has the network changed between starting Jitsi the first time and getting
the laptop out of sleep (so that the system got other DNS servers from
DHCP)?

I guess the network didn't change because I didn't move my laptop at all and the only network available to it was always my home wi-fi. Before I noticed the accounts had not automatically reconnected, I browsed a few pages in my browser and I received a couple of new e-mails.

Best regards,
Lyubomir


#8

This happened to me with r10431. When I tried to reproduce it with closing
the lid and opening right away it didn't happen. Then I tried to keep the
lid closed for some time and it happened again. I'm not sure whether the
timing is a coincidence or not. Logs are attached.

Regards,
Boris

jitsi0.log.0 (36.6 KB)


#9

Hey all,

I know it's a month late, but I wanted to chime into this conversation and offer some thoughts on these issues.

There are a number of issues to consider.

1. In the following class: net/java/sip/communicator/impl/protocol/sip/SipRegistrarConnection.java, if the register() function throws an exception when calling regTrans.sendRequest();, which appears to be the case when the internet connection has been dropped, the catch clause will execute sipProvider.registerUsingNextAddress() which will in turn call register() again. This will eventually lead to a StackOverflow.

2. Putting the machine to sleep appears to stop all timers. If the machine is awaken past the point of an expired registration, the proxy will not know to forward calls to Jitsi. If Jitsi attempts to register, but fails due to an invalid internet connection, then you end up in the above (#1) case. This can happen if a register() is called while the machine is attempting to reconnect.

3. This issue is less related to the above 2 issues. After the initial SRV lookups that occur when Jitsi starts, Jitsi will not attempt to make any further lookups. This appears to have to do with member variables not being properly cleared in the reset() function of Manual and Auto Proxy config classes. The net affect here is if the Proxy is updated to a new host IP, Jitsi will not discover this new host. This also violates TTL.

I hope this makes sense.

Oren Forer

···

On Feb 4, 2013, at 6:21 PM, Steve wrote:

I noticed this as well on OS X 10.8.2.

Jitsi used to auto-reconnect when the computer was put into sleep mode and then was woke up again. Now jitsi stays disconnected, despite the computer being wake. I can manually set the accounts to "online". But in previous builds this was not neccessary.

Best, steve

Am 04.02.2013 um 20:25 schrieb Lyubomir Marinov <lyubomir.marinov@jitsi.org>:

Hello, Ingo!

On 04.02.2013, at 21:14, "Ingo Bauersachs" <ingo@jitsi.org> wrote:

[...]
No server addresses found
[...]

Of course, restarting Jitsi does connect my accounts.

Has the network changed between starting Jitsi the first time and getting
the laptop out of sleep (so that the system got other DNS servers from
DHCP)?

I guess the network didn't change because I didn't move my laptop at all and the only network available to it was always my home wi-fi. Before I noticed the accounts had not automatically reconnected, I browsed a few pages in my browser and I received a couple of new e-mails.

Best regards,
Lyubomir


#10

It also happened to me quite often in the past few days. I supposed it
might be related to IP address changes.

Ingo, were you addressing this with your DNS resolver changes?

···

On 05.02.13, 14:47, Boris Grozev wrote:

This happened to me with r10431. When I tried to reproduce it with
closing the lid and opening right away it didn't happen. Then I tried to
keep the lid closed for some time and it happened again. I'm not sure
whether the timing is a coincidence or not. Logs are attached.

Regards,
Boris

--
https://jitsi.org


#11

Some more logs then.

It just happened to me. Kind of ... a reconnection did occur but it
happened 3 or four minutes later (while I was writing the e-mail).

Cheers,
Emil

2013-02-05@16.11.27-logs.zip (2.71 MB)

···

On 05.02.13, 15:22, Ingo Bauersachs wrote:

It also happened to me quite often in the past few days. I supposed it
might be related to IP address changes.

Ingo, were you addressing this with your DNS resolver changes?

I'm still trying to locate the issue as it doesn't occur on Windows.

Ingo

--
https://jitsi.org


#12

This happened to me with r10431. When I tried to reproduce it with closing
the lid and opening right away it didn't happen. Then I tried to keep the

lid

closed for some time and it happened again. I'm not sure whether the

timing

is a coincidence or not. Logs are attached.

Thanks Boris. I tried to get a clue, but I'm missing a line like
21:02:30.446 INFO: impl.dns.DnsUtilActivator.reloadDnsResolverConfig().174
Reloaded resolver config, default DNS servers are: 8.8.4.4, 8.8.8.8
in the log. So I'm wondering if the DNS service is at all registered? I've
committed a set of tiny patches to increase logging. Could you verify with
either a new test or by setting a breakpoint that the DNS service gets
actually started and is receiving events from the
NetworkAddressManagerService
(DnsUtilActivator$NetworkListener.configurationChanged().153)?

The log also shows that you have only one SystemActivityEvent listener,
while I have three of them. So there's definitely something different there.

Regards,
Boris

Ingo


#13

It also happened to me quite often in the past few days. I supposed it
might be related to IP address changes.

Ingo, were you addressing this with your DNS resolver changes?

I'm still trying to locate the issue as it doesn't occur on Windows.

Ingo


#14

I don't see 'DNS service ...[STARTED]' in the logs at all. The attached log
is from r10435.

Boris

jitsi0.log.0 (37.1 KB)

···

On Tue, Feb 5, 2013 at 10:19 PM, Ingo Bauersachs <ingo@jitsi.org> wrote:

Thanks Boris. I tried to get a clue, but I'm missing a line like
21:02:30.446 INFO: impl.dns.DnsUtilActivator.reloadDnsResolverConfig().174
Reloaded resolver config, default DNS servers are: 8.8.4.4, 8.8.8.8
in the log. So I'm wondering if the DNS service is at all registered? I've
committed a set of tiny patches to increase logging. Could you verify with
either a new test or by setting a breakpoint that the DNS service gets
actually started and is receiving events from the
NetworkAddressManagerService
(DnsUtilActivator$NetworkListener.configurationChanged().153)?


#15

I don't see 'DNS service ...[STARTED]' in the logs at all. The attached

log

is from r10435.

Are you sure this is from 10435 (and built with that revision)? The log line
that says it doesn't find any SRV addresses changed in 10434 and is still
the old one in your log...

Could you do a Wireshark trace during a failing connect phase?

Boris

Ingo