Smack 4.4.0-alpha2 SmackReactor reactorLoop die unexpectedly causing PingManager not working

Smack Smack Dev
1

Few months back, aTalk users compliant aTalk is unable to receive call while device is in standby. I also encountered that aTalk get disconnected when the device goes into idle during system testing. Only recently I have the time to investigate the problem.

aTalk uses Smack 4.4.0 for its Ping implementation since aTalk v1.5.1.(09/01/2018). But strange is that the ping function is still working in aTalk v1.5.6 (10/16/2018) while aTalk implementing Ping Interval auto-tune optimization. This was the last time Ping function is being actively tested.

On investigation, found that aTalk ping is not running at all; since smack 4.4.0, it changes the implementation of PingManager to use SmackReactor for call back for its Runnable;pingServerRunnable to execute pingServerIfNecessary(). Following are my observations:

  1. PingManager performs maybeSchedulePingServerTask(in delta) whenever aTalk executes:
    a. connection.connect()
    b. pingManager.setPingInterval(pingInterval);
    c. connection.login(userName, password, resource)
    So the maybeSchedulePingServerTask was being executed 3 times; however tracing shows that there is no problem and SmackReactor#scheduledActions are configured properly.

  2. SmackReactor#Reactor extends Thread starts up while scheduledActions is still empty i.e. before it is being scheduled by PingManager . Below are the added logcat debug messages; and reactorLoop() is found to execute only twice and die.

2019-05-31 09:30:11.381 26989-27764/org.atalk.android W/(SmackReactor.java:186)#reactorLoop: reactorLoop started: -1
2019-05-31 09:30:11.390 26989-27764/org.atalk.android W/(SmackReactor.java:197)#handleScheduledActionsOrPerformSelect: scheduledActions Size: 0
2019-05-31 09:30:11.396 26989-27764/org.atalk.android W/(SmackReactor.java:208)#handleScheduledActionsOrPerformSelect: dueScheduledAction: null
2019-05-31 09:30:11.406 26989-27765/org.atalk.android W/(SmackReactor.java:186)#reactorLoop: reactorLoop started: -1
2019-05-31 09:30:11.413 26989-27765/org.atalk.android W/(SmackReactor.java:197)#handleScheduledActionsOrPerformSelect: scheduledActions Size: 0
2019-05-31 09:30:11.420 26989-27765/org.atalk.android W/(SmackReactor.java:208)#handleScheduledActionsOrPerformSelect: dueScheduledAction: null

  1. PingManager#pingServerRunnable never get callback from SmackReactor, hence the ping is not performed.

Not sure what kill reactorLoop(). Since the loop is killed, I am unable to check if the scheduledActions content is empty. Can aTalk unintended action kill the reactorLoop()?

Any advice on how to find the cause?

2

With reference to SmackReactor, further investigations show that:

while scheduledActions is still empty, it executes line#352 i.e.:

newSelectedKeysCount = selector.select(selectWait);

with selectWait=0, that puts the Selector into blocking selection operation i.e.

public abstract int select(long timeout)

* This method performs a blocking selection
* operation. It returns only after at least one channel is selected,
* this selector’s {@link #wakeup wakeup} method is invoked, the current
* thread is interrupted, or the given timeout period expires, whichever
* comes first.

After which, although there are new tasks being scheduled and scheduledActions is being populated;
I see there is no action being performed to wake the Selector. This causes all tasks remain in queue and not being executed.

3

You are right, there is a selector.wakeup() missing in SmackReactor.schedule(). Thanks for reporting this. :+1:

I’ll have a fix ready soon.

4

Fixed with

5

Thanks for the patch. I have observed another race condition in SmackReactor execution during aTalk testing with your proposed patch.

If a new action to be scheduled is received after the selectWait has been initialized and prior to the synchronized (selector) block. There would be a problem if the new scheduled delay is earlier than the earlier fetched selectWait. The new scheduled action will only be executed only upon the longer selectWait timeout. The below patch fixed this race condition (in addition to your patch).

SmackReactor.patch (2.2 KB)

The following is aTalk debug log without the patch, using the modified source as attached below. The ping interval is set to 20 seconds. Some of the pings are omitted when the race conditions happen.

SmackReactor.zip (4.6 KB)

============ aTalk debug log without the new patch ============

2019-06-04 10:07:14.972 26316-27093/org.atalk.android W/(SmackReactor.java:257)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 7; in: 557; org.jivesoftware.smack.AbstractXMPPConnection$7@9ae0459
2019-06-04 10:07:15.542 26316-27093/org.atalk.android E/(SmackReactor.java:208)#handleScheduledActionsOrPerformSelect: Selector execute: org.jivesoftware.smack.AbstractXMPPConnection$7@9ae0459
2019-06-04 10:07:15.542 26316-27092/org.atalk.android W/(SmackReactor.java:257)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 6; in: 632; org.jivesoftware.smack.AbstractXMPPConnection$7@9ae0459
2019-06-04 10:07:16.189 26316-27093/org.atalk.android W/(SmackReactor.java:257)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 6; in: 19407; org.jivesoftware.smackx.ping.PingManager$9@435b327
2019-06-04 10:07:35.629 26316-27093/org.atalk.android E/(SmackReactor.java:208)#handleScheduledActionsOrPerformSelect: Selector execute: org.jivesoftware.smackx.ping.PingManager$9@435b327
2019-06-04 10:07:35.629 26316-27092/org.atalk.android W/(SmackReactor.java:257)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 5; in: 18772; org.jivesoftware.smackx.ping.PingManager$9@435b327
2019-06-04 10:07:35.644 26316-27093/org.atalk.android W/(SmackReactor.java:157)#schedule: Selector Schedule new action 119999 : org.jivesoftware.smack.AbstractXMPPConnection$7@a8749cd
2019-06-04 10:07:35.653 26316-27092/org.atalk.android W/(SmackReactor.java:257)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 6; in: 12; org.jivesoftware.smack.AbstractXMPPConnection$7@d2b68ff
2019-06-04 10:07:35.654 26316-27121/org.atalk.android D/SMACK: SENT (0): 
    <iq to='atalk.org' id='fkFHJ-114' type='get'>
      <ping xmlns='urn:xmpp:ping'/>
    </iq>
    <r xmlns='urn:xmpp:sm:3'/>
2019-06-04 10:07:35.670 26316-27092/org.atalk.android E/(SmackReactor.java:208)#handleScheduledActionsOrPerformSelect: Selector execute: org.jivesoftware.smack.AbstractXMPPConnection$7@d2b68ff
2019-06-04 10:07:35.675 26316-27093/org.atalk.android W/(SmackReactor.java:257)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 5; in: 9; org.jivesoftware.smack.AbstractXMPPConnection$7@d2b68ff
2019-06-04 10:07:35.689 26316-27092/org.atalk.android W/(SmackReactor.java:257)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 5; in: 20094; org.jivesoftware.smack.AbstractXMPPConnection$7@7318d15
2019-06-04 10:07:35.701 26316-27122/org.atalk.android D/SMACK: RECV (0): 
    <a h='25' xmlns='urn:xmpp:sm:3'/>
2019-06-04 10:07:35.706 26316-27122/org.atalk.android D/SMACK: RECV (0): 
    <iq xml:lang='en' to='swordfish@atalk.org/atalk' from='atalk.org' type='result' id='fkFHJ-114'/>
2019-06-04 10:07:35.715 26316-27122/org.atalk.android D/SMACK: RECV (0): 
    <r xmlns='urn:xmpp:sm:3'/>
2019-06-04 10:07:35.720 26316-27121/org.atalk.android D/SMACK: SENT (0): 
    <a xmlns='urn:xmpp:sm:3' h='28'/>
2019-06-04 10:07:35.723 26316-27576/org.atalk.android W/(SmackReactor.java:157)#schedule: Selector Schedule new action 19999 : org.jivesoftware.smackx.ping.PingManager$9@435b327
2019-06-04 10:07:35.728 26316-27093/org.atalk.android W/(SmackReactor.java:257)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 6; in: 20085; org.jivesoftware.smack.AbstractXMPPConnection$7@7318d15
2019-06-04 10:07:49.618 26316-26965/org.atalk.android W/libEGL: EGLNativeWindowType 0x7a21d84010 disconnect failed
2019-06-04 10:07:49.618 26316-26965/org.atalk.android D/OpenGLRenderer: eglDestroySurface = 0x7a09c3fc00, 0x7a21d84000
2019-06-04 10:07:49.690 26316-26316/org.atalk.android D/ViewRootImpl@936bd25[aTalk]: Relayout returned: old=[0,0][1080,2094] new=[0,0][1080,2094] result=0x5 surface={valid=false 0} changed=true
2019-06-04 10:07:55.845 26316-27093/org.atalk.android E/(SmackReactor.java:208)#handleScheduledActionsOrPerformSelect: Selector execute: org.jivesoftware.smackx.ping.PingManager$9@435b327
2019-06-04 10:07:55.846 26316-27092/org.atalk.android W/(SmackReactor.java:257)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 5; in: 19994; org.jivesoftware.smackx.ping.PingManager$9@435b327
2019-06-04 10:07:55.860 26316-27093/org.atalk.android W/(SmackReactor.java:157)#schedule: Selector Schedule new action 119998 : org.jivesoftware.smack.AbstractXMPPConnection$7@bf6e1d0
2019-06-04 10:07:55.867 26316-27092/org.atalk.android E/(SmackReactor.java:208)#handleScheduledActionsOrPerformSelect: Selector execute: org.jivesoftware.smack.AbstractXMPPConnection$7@7318d15
2019-06-04 10:07:55.868 26316-27121/org.atalk.android D/SMACK: SENT (0): 
    <iq to='atalk.org' id='fkFHJ-116' type='get'>
      <ping xmlns='urn:xmpp:ping'/>
    </iq>
2019-06-04 10:07:55.874 26316-27092/org.atalk.android W/(SmackReactor.java:257)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 5; in: 20020; org.jivesoftware.smack.AbstractXMPPConnection$7@757961b
2019-06-04 10:07:55.919 26316-27122/org.atalk.android D/SMACK: RECV (0): 
    <iq xml:lang='en' to='swordfish@atalk.org/atalk' from='atalk.org' type='result' id='fkFHJ-116'/>
2019-06-04 10:07:55.940 26316-27122/org.atalk.android D/SMACK: RECV (0): 
    <r xmlns='urn:xmpp:sm:3'/>
2019-06-04 10:07:55.946 26316-27118/org.atalk.android W/(SmackReactor.java:157)#schedule: Selector Schedule new action 19999 : org.jivesoftware.smackx.ping.PingManager$9@435b327
2019-06-04 10:07:55.948 26316-27121/org.atalk.android D/SMACK: SENT (0): 
    <a xmlns='urn:xmpp:sm:3' h='29'/>
2019-06-04 10:07:55.957 26316-27092/org.atalk.android W/(SmackReactor.java:257)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 6; in: 19938; org.jivesoftware.smack.AbstractXMPPConnection$7@757961b
2019-06-04 10:08:15.926 26316-27092/org.atalk.android E/(SmackReactor.java:208)#handleScheduledActionsOrPerformSelect: Selector execute: org.jivesoftware.smack.AbstractXMPPConnection$7@757961b
2019-06-04 10:08:15.927 26316-27093/org.atalk.android W/(SmackReactor.java:257)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 5; in: 20018; org.jivesoftware.smack.AbstractXMPPConnection$7@757961b
2019-06-04 10:08:35.977 26316-27093/org.atalk.android E/(SmackReactor.java:208)#handleScheduledActionsOrPerformSelect: Selector execute: org.jivesoftware.smackx.ping.PingManager$9@435b327
2019-06-04 10:08:35.977 26316-27092/org.atalk.android W/(SmackReactor.java:257)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 4; in: 7; org.jivesoftware.smackx.ping.PingManager$9@435b327
2019-06-04 10:08:35.991 26316-27093/org.atalk.android W/(SmackReactor.java:157)#schedule: Selector Schedule new action 119999 : org.jivesoftware.smack.AbstractXMPPConnection$7@595d4ce
2019-06-04 10:08:36.002 26316-27092/org.atalk.android W/(SmackReactor.java:257)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 5; in: 21; org.jivesoftware.smack.AbstractXMPPConnection$7@a2ae591
2019-06-04 10:08:36.007 26316-27121/org.atalk.android D/SMACK: SENT (0): 
    <iq to='atalk.org' id='fkFHJ-118' type='get'>
      <ping xmlns='urn:xmpp:ping'/>
    </iq>
2019-06-04 10:08:36.008 26316-27092/org.atalk.android W/(SmackReactor.java:257)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 5; in: 6; org.jivesoftware.smack.AbstractXMPPConnection$7@a2ae591
2019-06-04 10:08:36.019 26316-27092/org.atalk.android E/(SmackReactor.java:208)#handleScheduledActionsOrPerformSelect: Selector execute: org.jivesoftware.smack.AbstractXMPPConnection$7@a2ae591
2019-06-04 10:08:36.020 26316-27093/org.atalk.android W/(SmackReactor.java:257)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 4; in: 5; org.jivesoftware.smack.AbstractXMPPConnection$7@a2ae591
2019-06-04 10:08:36.031 26316-27092/org.atalk.android W/(SmackReactor.java:257)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 4; in: 38850; org.jivesoftware.smack.AbstractXMPPConnection$7@54f78f7
2019-06-04 10:08:36.051 26316-27122/org.atalk.android D/SMACK: RECV (0): 
    <iq xml:lang='en' to='swordfish@atalk.org/atalk' from='atalk.org' type='result' id='fkFHJ-118'/>
2019-06-04 10:08:36.063 26316-27122/org.atalk.android D/SMACK: RECV (0): 
    <r xmlns='urn:xmpp:sm:3'/>
2019-06-04 10:08:36.066 26316-27230/org.atalk.android W/(SmackReactor.java:157)#schedule: Selector Schedule new action 19999 : org.jivesoftware.smackx.ping.PingManager$9@435b327
2019-06-04 10:08:36.068 26316-27121/org.atalk.android D/SMACK: SENT (0): 
    <a xmlns='urn:xmpp:sm:3' h='30'/>
2019-06-04 10:08:36.074 26316-27093/org.atalk.android W/(SmackReactor.java:257)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 5; in: 38844; org.jivesoftware.smack.AbstractXMPPConnection$7@54f78f7
2019-06-04 10:09:14.968 26316-27093/org.atalk.android E/(SmackReactor.java:208)#handleScheduledActionsOrPerformSelect: Selector execute: org.jivesoftware.smackx.ping.PingManager$9@435b327
2019-06-04 10:09:14.969 26316-27092/org.atalk.android W/(SmackReactor.java:257)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 4; in: 19990; org.jivesoftware.smackx.ping.PingManager$9@435b327
2019-06-04 10:09:14.982 26316-27093/org.atalk.android W/(SmackReactor.java:157)#schedule: Selector Schedule new action 119998 : org.jivesoftware.smack.AbstractXMPPConnection$7@6b04afc
2019-06-04 10:09:14.994 26316-27092/org.atalk.android E/(SmackReactor.java:208)#handleScheduledActionsOrPerformSelect: Selector execute: org.jivesoftware.smack.AbstractXMPPConnection$7@54f78f7
2019-06-04 10:09:14.990 26316-27121/org.atalk.android D/SMACK: SENT (0): 
    <iq to='atalk.org' id='fkFHJ-120' type='get'>
      <ping xmlns='urn:xmpp:ping'/>
    </iq>
2019-06-04 10:09:14.995 26316-27093/org.atalk.android W/(SmackReactor.java:257)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 4; in: 20643; org.jivesoftware.smack.AbstractXMPPConnection$7@a8749cd
2019-06-04 10:09:15.041 26316-27122/org.atalk.android D/SMACK: RECV (0): 
    <iq xml:lang='en' to='swordfish@atalk.org/atalk' from='atalk.org' type='result' id='fkFHJ-120'/>
2019-06-04 10:09:15.058 26316-27230/org.atalk.android W/(SmackReactor.java:157)#schedule: Selector Schedule new action 19999 : org.jivesoftware.smackx.ping.PingManager$9@435b327
2019-06-04 10:09:15.067 26316-27122/org.atalk.android D/SMACK: RECV (0): 
    <r xmlns='urn:xmpp:sm:3'/>
2019-06-04 10:09:15.068 26316-27093/org.atalk.android W/(SmackReactor.java:257)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 5; in: 19987; org.jivesoftware.smackx.ping.PingManager$9@435b327
2019-06-04 10:09:15.072 26316-27121/org.atalk.android D/SMACK: SENT (0): 
    <a xmlns='urn:xmpp:sm:3' h='31'/>
2019-06-04 10:09:35.087 26316-27093/org.atalk.android E/(SmackReactor.java:208)#handleScheduledActionsOrPerformSelect: Selector execute: org.jivesoftware.smackx.ping.PingManager$9@435b327
2019-06-04 10:09:35.088 26316-27092/org.atalk.android W/(SmackReactor.java:257)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 4; in: 20636; org.jivesoftware.smack.AbstractXMPPConnection$7@a8749cd
2019-06-04 10:09:35.101 26316-27093/org.atalk.android W/(SmackReactor.java:157)#schedule: Selector Schedule new action 119999 : org.jivesoftware.smack.AbstractXMPPConnection$7@abe6fda
2019-06-04 10:09:35.110 26316-27121/org.atalk.android D/SMACK: SENT (0): 
    <iq to='atalk.org' id='fkFHJ-122' type='get'>
      <ping xmlns='urn:xmpp:ping'/>
    </iq>
2019-06-04 10:09:35.115 26316-27092/org.atalk.android W/(SmackReactor.java:257)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 5; in: 531; org.jivesoftware.smack.AbstractXMPPConnection$7@a8749cd
6

I am not sure about that. The selector.wakeup() call in schedule() should make the select() call in the reactor thread return immediately (see the javadoc of Selector.wakeup()). Which means the reactor thread which called select() will cycle once more through the reactor and eventually use the newer, earlier deadline for the next scheduled action.

Even if this is not the case, I don’t see how your proposed change to increase the synchronized block would help here, as Reactor.schedule() itself is not synchronized (and does not need to IMHO).

Are you sure that those scheduled actions where not just cancelled?

7

I am not sure about that. The selector.wakeup() call in schedule() should make the select() call in the reactor thread return immediately (see the javadoc of Selector.wakeup() ).

This is only true if the Selector is in the blocking selection operation wait state i.e. after the execution of

newSelectedKeysCount = selector.select(selectWait);

In this special case where Selector is not in the blocking selection operation wait state nor it in the Selector synchronized mode, the selector.waitup() in the schedule method is immediately consumed but does nothing to to the existing running thread; and the Selector will wait until the old selectWait is timeout.

If you review my previous debug log on the pings, you can see that the ping is not being executed at 20Sec regular interval, but skipped at times when the above race condition happen.

I move the the synchronized() before the next scheduledActions.peek(); i.e.

        synchronized (selector) {
            ScheduledAction nextScheduledAction = scheduledActions.peek();

            long selectWait;
            if (nextScheduledAction == null) {
                // There is no next scheduled action, wait indefinitely in select().
                selectWait = 0;
            } else {
                selectWait = nextScheduledAction.getTimeToDueMillis();
            }

By doing that, selector.waitup() in schedule method will be put on hold until Selector has entered blocking selection operation and the thread exited the synchronized() loop; only then the on hold selector.waitup() gets executed, and selectWait gets re-init with the correct value.

I have verified the new patch, the ping is being executed at 20S interval without missing a single one.
as captured below with my proposed patch.

2019-06-04 17:10:14.962 11557-1442/org.atalk.android D/SMACK: SENT (2): 
    <iq to='atalk.org' id='vJLSF-512' type='get'>
      <ping xmlns='urn:xmpp:ping'/>
    </iq>
2019-06-04 17:10:14.983 11557-1443/org.atalk.android D/SMACK: RECV (2): 
    <iq xml:lang='en' to='swordfish@atalk.org/atalk' from='atalk.org' type='result' id='vJLSF-512'/>
2019-06-04 17:10:14.989 11557-1443/org.atalk.android D/SMACK: RECV (2): 
    <r xmlns='urn:xmpp:sm:3'/>
2019-06-04 17:10:14.994 11557-1442/org.atalk.android D/SMACK: SENT (2): 
    <a xmlns='urn:xmpp:sm:3' h='25'/>
2019-06-04 17:10:35.023 11557-1442/org.atalk.android D/SMACK: SENT (2): 
    <iq to='atalk.org' id='vJLSF-514' type='get'>
      <ping xmlns='urn:xmpp:ping'/>
    </iq>
2019-06-04 17:10:35.045 11557-1443/org.atalk.android D/SMACK: RECV (2): 
    <iq xml:lang='en' to='swordfish@atalk.org/atalk' from='atalk.org' type='result' id='vJLSF-514'/>
2019-06-04 17:10:35.058 11557-1443/org.atalk.android D/SMACK: RECV (2): 
    <r xmlns='urn:xmpp:sm:3'/>
2019-06-04 17:10:35.062 11557-1442/org.atalk.android D/SMACK: SENT (2): 
    <a xmlns='urn:xmpp:sm:3' h='26'/>
2019-06-04 17:10:55.090 11557-1442/org.atalk.android D/SMACK: SENT (2): 
    <iq to='atalk.org' id='vJLSF-516' type='get'>
      <ping xmlns='urn:xmpp:ping'/>
    </iq>
2019-06-04 17:10:55.108 11557-1443/org.atalk.android D/SMACK: RECV (2): 
    <iq xml:lang='en' to='swordfish@atalk.org/atalk' from='atalk.org' type='result' id='vJLSF-516'/>
2019-06-04 17:10:55.116 11557-1443/org.atalk.android D/SMACK: RECV (2): 
    <r xmlns='urn:xmpp:sm:3'/>
2019-06-04 17:10:55.122 11557-1442/org.atalk.android D/SMACK: SENT (2): 
    <a xmlns='urn:xmpp:sm:3' h='27'/>
2019-06-04 17:11:15.151 11557-1442/org.atalk.android D/SMACK: SENT (2): 
    <iq to='atalk.org' id='vJLSF-518' type='get'>
      <ping xmlns='urn:xmpp:ping'/>
    </iq>
2019-06-04 17:11:15.157 11557-1442/org.atalk.android D/SMACK: SENT (2): 
    <r xmlns='urn:xmpp:sm:3'/>
2019-06-04 17:11:15.169 11557-1443/org.atalk.android D/SMACK: RECV (2): 
    <iq xml:lang='en' to='swordfish@atalk.org/atalk' from='atalk.org' type='result' id='vJLSF-518'/>
2019-06-04 17:11:15.178 11557-1443/org.atalk.android D/SMACK: RECV (2): 
    <r xmlns='urn:xmpp:sm:3'/>
2019-06-04 17:11:15.181 11557-1442/org.atalk.android D/SMACK: SENT (2): 
    <a xmlns='urn:xmpp:sm:3' h='28'/>
2019-06-04 17:11:15.186 11557-1443/org.atalk.android D/SMACK: RECV (2): 
    <a h='20' xmlns='urn:xmpp:sm:3'/>
2019-06-04 17:11:35.215 11557-1442/org.atalk.android D/SMACK: SENT (2): 
    <iq to='atalk.org' id='vJLSF-520' type='get'>
      <ping xmlns='urn:xmpp:ping'/>
    </iq>
2019-06-04 17:11:35.229 11557-1443/org.atalk.android D/SMACK: RECV (2): 
    <iq xml:lang='en' to='swordfish@atalk.org/atalk' from='atalk.org' type='result' id='vJLSF-520'/>
2019-06-04 17:11:35.241 11557-1443/org.atalk.android D/SMACK: RECV (2): 
    <r xmlns='urn:xmpp:sm:3'/>
2019-06-04 17:11:35.243 11557-1442/org.atalk.android D/SMACK: SENT (2): 
    <a xmlns='urn:xmpp:sm:3' h='29'/>
2019-06-04 17:11:55.274 11557-1442/org.atalk.android D/SMACK: SENT (2): 
    <iq to='atalk.org' id='vJLSF-522' type='get'>
      <ping xmlns='urn:xmpp:ping'/>
    </iq>
2019-06-04 17:11:55.300 11557-1443/org.atalk.android D/SMACK: RECV (2): 
    <iq xml:lang='en' to='swordfish@atalk.org/atalk' from='atalk.org' type='result' id='vJLSF-522'/>
2019-06-04 17:11:55.312 11557-1443/org.atalk.android D/SMACK: RECV (2): 
    <r xmlns='urn:xmpp:sm:3'/>
2019-06-04 17:11:55.319 11557-1442/org.atalk.android D/SMACK: SENT (2): 
    <a xmlns='urn:xmpp:sm:3' h='30'/>
2019-06-04 17:12:15.331 11557-1442/org.atalk.android D/SMACK: SENT (2): 
    <iq to='atalk.org' id='vJLSF-524' type='get'>
      <ping xmlns='urn:xmpp:ping'/>
    </iq>
2019-06-04 17:12:15.350 11557-1443/org.atalk.android D/SMACK: RECV (2): 
    <iq xml:lang='en' to='swordfish@atalk.org/atalk' from='atalk.org' type='result' id='vJLSF-524'/>
2019-06-04 17:12:15.357 11557-1443/org.atalk.android D/SMACK: RECV (2): 
    <r xmlns='urn:xmpp:sm:3'/>
2019-06-04 17:12:15.360 11557-1442/org.atalk.android D/SMACK: SENT (2): 
    <a xmlns='urn:xmpp:sm:3' h='31'/>

If I revert my proposed patch, below is the new captured log under the same test conditions. The third ping get sent only after a delay of 99 seconds instead of 20s.

2019-06-04 17:16:43.723 2279-3146/org.atalk.android D/SMACK: SENT (0): 
    <iq to='atalk.org' id='OkwOr-104' type='get'>
      <ping xmlns='urn:xmpp:ping'/>
    </iq>
2019-06-04 17:16:43.740 2279-3147/org.atalk.android D/SMACK: RECV (0): 
    <iq xml:lang='en' to='swordfish@atalk.org/atalk' from='atalk.org' type='result' id='OkwOr-104'/>
2019-06-04 17:16:43.754 2279-3147/org.atalk.android D/SMACK: RECV (0): 
    <r xmlns='urn:xmpp:sm:3'/>
2019-06-04 17:16:43.759 2279-3146/org.atalk.android D/SMACK: SENT (0): 
    <a xmlns='urn:xmpp:sm:3' h='25'/>
2019-06-04 17:17:04.030 2279-3146/org.atalk.android D/SMACK: SENT (0): 
    <iq to='atalk.org' id='OkwOr-106' type='get'>
      <ping xmlns='urn:xmpp:ping'/>
    </iq>
2019-06-04 17:17:04.052 2279-3147/org.atalk.android D/SMACK: RECV (0): 
    <iq xml:lang='en' to='swordfish@atalk.org/atalk' from='atalk.org' type='result' id='OkwOr-106'/>
2019-06-04 17:17:04.075 2279-3147/org.atalk.android D/SMACK: RECV (0): 
    <r xmlns='urn:xmpp:sm:3'/>
2019-06-04 17:17:04.082 2279-3146/org.atalk.android D/SMACK: SENT (0): 
    <a xmlns='urn:xmpp:sm:3' h='26'/>
2019-06-04 17:18:43.882 2279-3146/org.atalk.android D/SMACK: SENT (0): 
    <iq to='atalk.org' id='OkwOr-108' type='get'>
      <ping xmlns='urn:xmpp:ping'/>
    </iq>
2019-06-04 17:18:43.902 2279-3147/org.atalk.android D/SMACK: RECV (0): 
    <iq xml:lang='en' to='swordfish@atalk.org/atalk' from='atalk.org' type='result' id='OkwOr-108'/>
2019-06-04 17:18:43.920 2279-3147/org.atalk.android D/SMACK: RECV (0): 
    <r xmlns='urn:xmpp:sm:3'/>
2019-06-04 17:18:43.924 2279-3146/org.atalk.android D/SMACK: SENT (0): 
    <a xmlns='urn:xmpp:sm:3' h='27'/>
2019-06-04 17:19:03.981 2279-3146/org.atalk.android D/SMACK: SENT (0): 
    <iq to='atalk.org' id='OkwOr-110' type='get'>
      <ping xmlns='urn:xmpp:ping'/>
    </iq>
    <r xmlns='urn:xmpp:sm:3'/>
2019-06-04 17:19:03.994 2279-3147/org.atalk.android D/SMACK: RECV (0): 
    <a h='20' xmlns='urn:xmpp:sm:3'/>
2019-06-04 17:19:04.001 2279-3147/org.atalk.android D/SMACK: RECV (0): 
    <iq xml:lang='en' to='swordfish@atalk.org/atalk' from='atalk.org' type='result' id='OkwOr-110'/>
2019-06-04 17:19:04.017 2279-3147/org.atalk.android D/SMACK: RECV (0): 
    <r xmlns='urn:xmpp:sm:3'/>
2019-06-04 17:19:04.023 2279-3146/org.atalk.android D/SMACK: SENT (0): 
    <a xmlns='urn:xmpp:sm:3' h='28'/>
2019-06-04 17:19:24.093 2279-3146/org.atalk.android D/SMACK: SENT (0): 
    <iq to='atalk.org' id='OkwOr-112' type='get'>
      <ping xmlns='urn:xmpp:ping'/>
    </iq>
2019-06-04 17:19:24.106 2279-3147/org.atalk.android D/SMACK: RECV (0): 
    <iq xml:lang='en' to='swordfish@atalk.org/atalk' from='atalk.org' type='result' id='OkwOr-112'/>
2019-06-04 17:19:24.123 2279-3147/org.atalk.android D/SMACK: RECV (0): 
    <r xmlns='urn:xmpp:sm:3'/>
2019-06-04 17:19:24.129 2279-3146/org.atalk.android D/SMACK: SENT (0): 
    <a xmlns='urn:xmpp:sm:3' h='29'/>
2019-06-04 17:20:44.003 2279-3146/org.atalk.android D/SMACK: SENT (0): 
    <iq to='atalk.org' id='OkwOr-114' type='get'>
      <ping xmlns='urn:xmpp:ping'/>
    </iq>
2019-06-04 17:20:44.024 2279-3147/org.atalk.android D/SMACK: RECV (0): 
    <iq xml:lang='en' to='swordfish@atalk.org/atalk' from='atalk.org' type='result' id='OkwOr-114'/>
2019-06-04 17:20:44.042 2279-3147/org.atalk.android D/SMACK: RECV (0): 
    <r xmlns='urn:xmpp:sm:3'/>
2019-06-04 17:20:44.048 2279-3146/org.atalk.android D/SMACK: SENT (0): 
    <a xmlns='urn:xmpp:sm:3' h='30'/>:
8

The javadoc of Selector.wakeup() states

If no selection operation is currently in progress then the next invocation of one of these methods will return immediately

That is not what I would expect to happen. Either the reactor thread is blocking in select() at the time another thread invokes wakeup(), in this case select() returns. Or there is currently no reactor thread in select() blocking, in this case, one will eventually reach the select() method, but it will immediately return, as per the previous cited javadoc, since there was a call to wakeup() in between.

Note that I am not saying that there is no issue here. There may be one, but I first want to make sure that we both understand what is going on.

9

Yes, you are right.

If no selection operation is currently in progress then the next invocation of one of these methods will return immediately

Look like I need to do more investigation why the patch help.

10

Following is my new observation using the attached modified source without the new patch.

SmackReactor.zip (4.6 KB)

The Selector does follow the java doc. it returns on invocation of selector method as stated below:

If no selection operation is currently in progress then the next invocation of one of these methods will return immediately

Below describes the sequence of event that lead to the problem:

  1. @00:39:15.063, after it has scheduled the next action i.e. AbstractXMPPConnection$7@8978830
  2. @00:39:15.098, it received the new scheduledAction PingManager$9@d37afe5
  3. @00:39:15.103, the selector wakeup and begin a new cycle
  4. @00:39:15.108, the peek however fetches the previous AbstractXMPPConnection$7@8978830 instead of the newly added PingManager$9@d37afe5; with selectWait of 99,690ms
  5. @00:40:54.895, Hence the ping get executed only 99 seconds after the previous ping.

The problem is why the new peek failed to fetch the new ping action; even though scheduledActions did contain the newly added ping action i.e. size of 3. Unless the scheduledActions has not being properly order yet.

I am still unable to explain why the new patch helps to synchronize scheduledActions into proper order,
so the peek get the newly added ping action.

2019-06-05 00:39:08.052 29844-30737/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0
2019-06-05 00:39:08.065 29844-30737/org.atalk.android E/(SmackReactor.java:206)#handleScheduledActionsOrPerformSelect: Selector execute: org.jivesoftware.smack.AbstractXMPPConnection$7@6931dbf
2019-06-05 00:39:08.068 29844-30743/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 2; in: 225; org.jivesoftware.smack.AbstractXMPPConnection$7@6931dbf
2019-06-05 00:39:08.303 29844-30743/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0
2019-06-05 00:39:08.315 29844-30737/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 2; in: 6719; org.jivesoftware.smackx.ping.PingManager$9@d37afe5
2019-06-05 00:39:15.044 29844-30737/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0
2019-06-05 00:39:15.048 29844-30737/org.atalk.android E/(SmackReactor.java:206)#handleScheduledActionsOrPerformSelect: Selector execute: org.jivesoftware.smackx.ping.PingManager$9@d37afe5
2019-06-05 00:39:15.049 29844-30743/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 1; in: 6480; org.jivesoftware.smackx.ping.PingManager$9@d37afe5
2019-06-05 00:39:15.055 29844-30737/org.atalk.android W/(SmackReactor.java:155)#schedule: Selector Schedule new action 119999 : org.jivesoftware.smack.AbstractXMPPConnection$7@4fd22e
2019-06-05 00:39:15.059 29844-30743/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0
2019-06-05 00:39:15.062 29844-30752/org.atalk.android D/SMACK: SENT (0): 
    <iq to='atalk.org' id='NKmYO-108' type='get'>
      <ping xmlns='urn:xmpp:ping'/>
    </iq>
2019-06-05 00:39:15.063 29844-30737/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 2; in: 99692; org.jivesoftware.smack.AbstractXMPPConnection$7@8978830
2019-06-05 00:39:15.084 29844-30753/org.atalk.android D/SMACK: RECV (0): 
    <iq xml:lang='en' to='swordfish@atalk.org/atalk' from='atalk.org' type='result' id='NKmYO-108'/>
2019-06-05 00:39:15.096 29844-30753/org.atalk.android D/SMACK: RECV (0): 
    <r xmlns='urn:xmpp:sm:3'/>
2019-06-05 00:39:15.098 29844-30798/org.atalk.android W/(SmackReactor.java:155)#schedule: Selector Schedule new action 19998 : org.jivesoftware.smackx.ping.PingManager$9@d37afe5
2019-06-05 00:39:15.101 29844-30752/org.atalk.android D/SMACK: SENT (0): 
    <a xmlns='urn:xmpp:sm:3' h='27'/>
2019-06-05 00:39:15.103 29844-30737/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0

### cmeng: the peek fetches the previous scheduledAction instead of the newly added ping action
### Hence the ping get executed only after 99 seconds
2019-06-05 00:39:15.108 29844-30743/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 3; in: 99690; org.jivesoftware.smack.AbstractXMPPConnection$7@8978830

2019-06-05 00:40:54.882 29844-30743/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0
2019-06-05 00:40:54.895 29844-30743/org.atalk.android E/(SmackReactor.java:206)#handleScheduledActionsOrPerformSelect: Selector execute: org.jivesoftware.smackx.ping.PingManager$9@d37afe5
2019-06-05 00:40:54.896 29844-30737/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 2; in: 19988; org.jivesoftware.smackx.ping.PingManager$9@d37afe5
2019-06-05 00:40:54.910 29844-30743/org.atalk.android W/(SmackReactor.java:155)#schedule: Selector Schedule new action 119997 : org.jivesoftware.smack.AbstractXMPPConnection$7@7cade90
2019-06-05 00:40:54.915 29844-30737/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0
2019-06-05 00:40:54.918 29844-30743/org.atalk.android E/(SmackReactor.java:206)#handleScheduledActionsOrPerformSelect: Selector execute: org.jivesoftware.smack.AbstractXMPPConnection$7@8978830
2019-06-05 00:40:54.922 29844-30737/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 2; in: 20134; org.jivesoftware.smack.AbstractXMPPConnection$7@4fd22e
2019-06-05 00:40:54.924 29844-30752/org.atalk.android D/SMACK: SENT (0): 
    <iq to='atalk.org' id='NKmYO-110' type='get'>
      <ping xmlns='urn:xmpp:ping'/>
    </iq>
    <r xmlns='urn:xmpp:sm:3'/>
11

Below is another strange behavior that I observed this morning:

  1. @08:50:40.803, new action is received AbstractXMPPConnection$7@f4ff334 for schedule with 120,000ms
  2. @08:50:40.805, before the new action that added into scheduledActions (as size remains as 5), it proceed with the previous action with time 19,384ms
  3. @08:50:40.807, #2 get re-executed as a Selector.wakeup was triggered by #1.
  4. @08:50:40.841, after the ping @8:50:40.808, a new ping action is received
  5. @08:50:40.844, #3 get re-executed as a result of #4
  6. @08:51:00.233, the Selector waitup due to timeout of #5
    7.@08:51:00.235, strangely the expired #5 get schedule again with 19,397ms; and not the ping action, its selectWait may have reduce to a very small +ve value???.
  7. @08:51:00.236, #6 wakeup proceed to execute AbstractXMPPConnection$7@694ac9c. Note: this may actual happen before #7 as time delta is only 1ms

The problem again seems to have some race condition where action performed on scheduledActions before it is being properly updated?

Thinking that there may be too many unnecessary interruptions to wake the Selector, I modified the schedule() method as below. But this also does not improve anything.

    ScheduledAction schedule(Runnable runnable, long delay, TimeUnit unit)
    {
        long releaseTimeEpoch = System.currentTimeMillis() + unit.toMillis(delay);
        Date releaseTimeDate = new Date(releaseTimeEpoch);

        long waitInQueue = 0L;
        ScheduledAction queueAction = scheduledActions.peek();
        if (queueAction != null)
            waitInQueue = queueAction.getTimeToDueMillis();

        ScheduledAction scheduledAction = new ScheduledAction(runnable, releaseTimeDate, this);
        scheduledActions.add(scheduledAction);
        Timber.w("Selector Schedule new action %s (%s): %s",
                scheduledAction.getTimeToDueMillis(), waitInQueue, runnable);
        if ((scheduledActions.size() < 2) || (scheduledAction.getTimeToDueMillis() <= waitInQueue))
            selector.wakeup();
        return scheduledAction;
    }

2019-06-05 08:50:40.802 9268-9426/org.atalk.android E/(SmackReactor.java:206)#handleScheduledActionsOrPerformSelect: Selector execute: org.jivesoftware.smackx.ping.PingManager$9@cb86561
2019-06-05 08:50:40.803 9268-9426/org.atalk.android W/(SmackReactor.java:155)#schedule: Selector Schedule new action 120000 : org.jivesoftware.smack.AbstractXMPPConnection$7@f4ff334
2019-06-05 08:50:40.805 9268-9425/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 5; in: 19384; org.jivesoftware.smack.AbstractXMPPConnection$7@a7eb56e
2019-06-05 08:50:40.806 9268-9425/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0
2019-06-05 08:50:40.807 9268-9425/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 5; in: 19405; org.jivesoftware.smack.AbstractXMPPConnection$7@694ac9c
2019-06-05 08:50:40.808 9268-9453/org.atalk.android D/SMACK: SENT (0): 
    <iq to='atalk.org' id='1tIu9-2106' type='get'>
      <ping xmlns='urn:xmpp:ping'/>
    </iq>
2019-06-05 08:50:40.832 9268-9454/org.atalk.android D/SMACK: RECV (0): 
    <iq xml:lang='en' to='swordfish@atalk.org/atalk' from='atalk.org' type='result' id='1tIu9-2106'/>
2019-06-05 08:50:40.837 9268-9454/org.atalk.android D/SMACK: RECV (0): 
    <r xmlns='urn:xmpp:sm:3'/>
2019-06-05 08:50:40.841 9268-30378/org.atalk.android W/(SmackReactor.java:155)#schedule: Selector Schedule new action 20000 : org.jivesoftware.smackx.ping.PingManager$9@cb86561
2019-06-05 08:50:40.842 9268-9453/org.atalk.android D/SMACK: SENT (0): 
    <a xmlns='urn:xmpp:sm:3' h='1027'/>
2019-06-05 08:50:40.843 9268-9425/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0
2019-06-05 08:50:40.844 9268-9425/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 6; in: 19368; org.jivesoftware.smack.AbstractXMPPConnection$7@694ac9c
2019-06-05 08:51:00.233 9268-9425/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0
2019-06-05 08:51:00.235 9268-9426/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 6; in: 19397; org.jivesoftware.smack.AbstractXMPPConnection$7@694ac9c
2019-06-05 08:51:00.236 9268-9425/org.atalk.android E/(SmackReactor.java:206)#handleScheduledActionsOrPerformSelect: Selector execute: org.jivesoftware.smack.AbstractXMPPConnection$7@694ac9c
2019-06-05 08:51:19.656 9268-9426/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0
2019-06-05 08:51:19.658 9268-9426/org.atalk.android E/(SmackReactor.java:206)#handleScheduledActionsOrPerformSelect: Selector execute: org.jivesoftware.smackx.ping.PingManager$9@cb86561
2019-06-05 08:51:19.661 9268-9425/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 4; in: 604; org.jivesoftware.smackx.ping.PingManager$9@cb86561
2019-06-05 08:51:19.663 9268-9426/org.atalk.android W/(SmackReactor.java:155)#schedule: Selector Schedule new action 120000 : org.jivesoftware.smack.AbstractXMPPConnection$7@2dc1ed2
2019-06-05 08:51:19.666 9268-9453/org.atalk.android D/SMACK: SENT (0): 
    <iq to='atalk.org' id='1tIu9-2108' type='get'>
      <ping xmlns='urn:xmpp:ping'/>
    </iq>
12

I re-apply the new patch, still keeping all inserted log messages dump for comparison. I observed that similar sequence of events happen as before. However the re-peek always fetch the CORRECT selectTime for next in queue action. I checked the ping for the next 100 occurrences, I see none of the pings get omitted. Without the patch, the missing ping happen very often.

Sorry, I am still unable to explain why the new patch helps to resolve the race condition.

2019-06-05 10:22:25.053 11425-12098/org.atalk.android W/(SmackReactor.java:155)#schedule: Selector Schedule new action 19994 : org.jivesoftware.smackx.ping.PingManager$9@435b327
2019-06-05 10:22:25.059 11425-12062/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0
2019-06-05 10:22:25.066 11425-12061/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 4; in: 4816; org.jivesoftware.smack.AbstractXMPPConnection$7@d70a887
2019-06-05 10:22:29.895 11425-12061/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0
2019-06-05 10:22:29.907 11425-12062/org.atalk.android E/(SmackReactor.java:206)#handleScheduledActionsOrPerformSelect: Selector execute: org.jivesoftware.smack.AbstractXMPPConnection$7@d70a887
2019-06-05 10:22:29.910 11425-12061/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 3; in: 505; org.jivesoftware.smack.AbstractXMPPConnection$7@fdb1c8b
2019-06-05 10:22:30.426 11425-12061/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0
2019-06-05 10:22:30.436 11425-12061/org.atalk.android E/(SmackReactor.java:206)#handleScheduledActionsOrPerformSelect: Selector execute: org.jivesoftware.smack.AbstractXMPPConnection$7@fdb1c8b
2019-06-05 10:22:30.437 11425-12062/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 2; in: 14614; org.jivesoftware.smackx.ping.PingManager$9@435b327
2019-06-05 10:22:31.282 11425-12113/org.atalk.android I/(HttpUtils.java:175)#executeMethod: Auto checking for software update: GET https://atalk.sytes.net/releases/atalk-android/versionupdate.properties HTTP/1.1
2019-06-05 10:22:45.075 11425-12062/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0
2019-06-05 10:22:45.086 11425-12062/org.atalk.android E/(SmackReactor.java:206)#handleScheduledActionsOrPerformSelect: Selector execute: org.jivesoftware.smackx.ping.PingManager$9@435b327
2019-06-05 10:22:45.087 11425-12061/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 1; in: 99876; org.jivesoftware.smack.AbstractXMPPConnection$7@12274b7
2019-06-05 10:22:45.100 11425-12062/org.atalk.android W/(SmackReactor.java:155)#schedule: Selector Schedule new action 119999 : org.jivesoftware.smack.AbstractXMPPConnection$7@2aa8631
2019-06-05 10:22:45.105 11425-12061/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0
2019-06-05 10:22:45.110 11425-12061/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 2; in: 99849; org.jivesoftware.smack.AbstractXMPPConnection$7@12274b7
2019-06-05 10:22:45.110 11425-12069/org.atalk.android D/SMACK: SENT (0): 
    <iq to='atalk.org' id='HP8Xh-106' type='get'>
      <ping xmlns='urn:xmpp:ping'/>
    </iq>
2019-06-05 10:22:45.160 11425-12070/org.atalk.android D/SMACK: RECV (0): 
    <iq xml:lang='en' to='swordfish@atalk.org/atalk' from='atalk.org' type='result' id='HP8Xh-106'/>
2019-06-05 10:22:45.183 11425-12070/org.atalk.android D/SMACK: RECV (0): 
    <r xmlns='urn:xmpp:sm:3'/>
2019-06-05 10:22:45.190 11425-12069/org.atalk.android D/SMACK: SENT (0): 
    <a xmlns='urn:xmpp:sm:3' h='26'/>
2019-06-05 10:22:45.190 11425-12100/org.atalk.android W/(SmackReactor.java:155)#schedule: Selector Schedule new action 19999 : org.jivesoftware.smackx.ping.PingManager$9@435b327
2019-06-05 10:22:45.195 11425-12061/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0
2019-06-05 10:22:45.200 11425-12062/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 3; in: 19987; org.jivesoftware.smackx.ping.PingManager$9@435b327
2019-06-05 10:23:05.198 11425-12062/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0
2019-06-05 10:23:05.209 11425-12062/org.atalk.android E/(SmackReactor.java:206)#handleScheduledActionsOrPerformSelect: Selector execute: org.jivesoftware.smackx.ping.PingManager$9@435b327
2019-06-05 10:23:05.212 11425-12061/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 2; in: 79752; org.jivesoftware.smack.AbstractXMPPConnection$7@12274b7
2019-06-05 10:23:05.220 11425-12062/org.atalk.android W/(SmackReactor.java:155)#schedule: Selector Schedule new action 119998 : org.jivesoftware.smack.AbstractXMPPConnection$7@d889a97
2019-06-05 10:23:05.224 11425-12061/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0
2019-06-05 10:23:05.228 11425-12069/org.atalk.android D/SMACK: SENT (0): 
    <iq to='atalk.org' id='HP8Xh-108' type='get'>
      <ping xmlns='urn:xmpp:ping'/>
    </iq>
2019-06-05 10:23:05.230 11425-12061/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 3; in: 79729; org.jivesoftware.smack.AbstractXMPPConnection$7@12274b7
2019-06-05 10:23:05.278 11425-12070/org.atalk.android D/SMACK: RECV (0): 
    <iq xml:lang='en' to='swordfish@atalk.org/atalk' from='atalk.org' type='result' id='HP8Xh-108'/>
2019-06-05 10:23:05.300 11425-12100/org.atalk.android W/(SmackReactor.java:155)#schedule: Selector Schedule new action 19999 : org.jivesoftware.smackx.ping.PingManager$9@435b327
2019-06-05 10:23:05.305 11425-12070/org.atalk.android D/SMACK: RECV (0): 
    <r xmlns='urn:xmpp:sm:3'/>
2019-06-05 10:23:05.306 11425-12061/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0
2019-06-05 10:23:05.310 11425-12069/org.atalk.android D/SMACK: SENT (0): 
    <a xmlns='urn:xmpp:sm:3' h='27'/>
2019-06-05 10:23:05.316 11425-12062/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 4; in: 19980; org.jivesoftware.smackx.ping.PingManager$9@435b327
2019-06-05 10:23:25.324 11425-12062/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0
2019-06-05 10:23:25.334 11425-12062/org.atalk.android E/(SmackReactor.java:206)#handleScheduledActionsOrPerformSelect: Selector execute: org.jivesoftware.smackx.ping.PingManager$9@435b327
2019-06-05 10:23:25.336 11425-12061/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 3; in: 59627; org.jivesoftware.smack.AbstractXMPPConnection$7@12274b7
2019-06-05 10:23:25.344 11425-12062/org.atalk.android W/(SmackReactor.java:155)#schedule: Selector Schedule new action 119998 : org.jivesoftware.smack.AbstractXMPPConnection$7@f70546d
2019-06-05 10:23:25.348 11425-12061/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0
2019-06-05 10:23:25.356 11425-12061/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 4; in: 59606; org.jivesoftware.smack.AbstractXMPPConnection$7@12274b7
2019-06-05 10:23:25.358 11425-12069/org.atalk.android D/SMACK: SENT (0): 
    <iq to='atalk.org' id='HP8Xh-110' type='get'>
      <ping xmlns='urn:xmpp:ping'/>
    </iq>
    <r xmlns='urn:xmpp:sm:3'/>
2019-06-05 10:23:25.406 11425-12070/org.atalk.android D/SMACK: RECV (0): 
    <a h='20' xmlns='urn:xmpp:sm:3'/>
2019-06-05 10:23:25.420 11425-12070/org.atalk.android D/SMACK: RECV (0): 
    <iq xml:lang='en' to='swordfish@atalk.org/atalk' from='atalk.org' type='result' id='HP8Xh-110'/>
2019-06-05 10:23:25.442 11425-12070/org.atalk.android D/SMACK: RECV (0): 
    <r xmlns='urn:xmpp:sm:3'/>
2019-06-05 10:23:25.446 11425-12100/org.atalk.android W/(SmackReactor.java:155)#schedule: Selector Schedule new action 19994 : org.jivesoftware.smackx.ping.PingManager$9@435b327
2019-06-05 10:23:25.450 11425-12061/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0
2019-06-05 10:23:25.451 11425-12069/org.atalk.android D/SMACK: SENT (0): 
    <a xmlns='urn:xmpp:sm:3' h='28'/>
2019-06-05 10:23:25.456 11425-12062/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 5; in: 19985; org.jivesoftware.smackx.ping.PingManager$9@435b327
2019-06-05 10:23:45.469 11425-12062/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0
2019-06-05 10:23:45.488 11425-12062/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 4; in: 39474; org.jivesoftware.smack.AbstractXMPPConnection$7@12274b7
2019-06-05 10:23:45.490 11425-12061/org.atalk.android E/(SmackReactor.java:206)#handleScheduledActionsOrPerformSelect: Selector execute: org.jivesoftware.smackx.ping.PingManager$9@435b327
2019-06-05 10:23:45.497 11425-12061/org.atalk.android W/(SmackReactor.java:155)#schedule: Selector Schedule new action 120000 : org.jivesoftware.smack.AbstractXMPPConnection$7@2b24933
2019-06-05 10:23:45.501 11425-12062/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0
2019-06-05 10:23:45.509 11425-12062/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 5; in: 39453; org.jivesoftware.smack.AbstractXMPPConnection$7@12274b7
2019-06-05 10:23:45.509 11425-12069/org.atalk.android D/SMACK: SENT (0): 
    <iq to='atalk.org' id='HP8Xh-112' type='get'>
      <ping xmlns='urn:xmpp:ping'/>
    </iq>
2019-06-05 10:23:45.551 11425-12070/org.atalk.android D/SMACK: RECV (0): 
    <iq xml:lang='en' to='swordfish@atalk.org/atalk' from='atalk.org' type='result' id='HP8Xh-112'/>
2019-06-05 10:23:45.561 11425-12070/org.atalk.android D/SMACK: RECV (0): 
    <r xmlns='urn:xmpp:sm:3'/>
2019-06-05 10:23:45.565 11425-12069/org.atalk.android D/SMACK: SENT (0): 
    <a xmlns='urn:xmpp:sm:3' h='29'/>
2019-06-05 10:23:45.569 11425-12278/org.atalk.android W/(SmackReactor.java:155)#schedule: Selector Schedule new action 19999 : org.jivesoftware.smackx.ping.PingManager$9@435b327
2019-06-05 10:23:45.572 11425-12062/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0
2019-06-05 10:23:45.577 11425-12061/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 6; in: 19991; org.jivesoftware.smackx.ping.PingManager$9@435b327
2019-06-05 10:24:05.590 11425-12061/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0
2019-06-05 10:24:05.597 11425-12062/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 5; in: 19363; org.jivesoftware.smack.AbstractXMPPConnection$7@12274b7
2019-06-05 10:24:05.602 11425-12061/org.atalk.android E/(SmackReactor.java:206)#handleScheduledActionsOrPerformSelect: Selector execute: org.jivesoftware.smackx.ping.PingManager$9@435b327
2019-06-05 10:24:05.611 11425-12061/org.atalk.android W/(SmackReactor.java:155)#schedule: Selector Schedule new action 120000 : org.jivesoftware.smack.AbstractXMPPConnection$7@aba5cee
2019-06-05 10:24:05.615 11425-12062/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0
2019-06-05 10:24:05.624 11425-12062/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 6; in: 19339; org.jivesoftware.smack.AbstractXMPPConnection$7@12274b7
2019-06-05 10:24:05.625 11425-12069/org.atalk.android D/SMACK: SENT (0): 
    <iq to='atalk.org' id='HP8Xh-114' type='get'>
      <ping xmlns='urn:xmpp:ping'/>
    </iq>
2019-06-05 10:24:05.642 11425-12070/org.atalk.android D/SMACK: RECV (0): 
    <iq xml:lang='en' to='swordfish@atalk.org/atalk' from='atalk.org' type='result' id='HP8Xh-114'/>
2019-06-05 10:24:05.651 11425-12070/org.atalk.android D/SMACK: RECV (0): 
    <r xmlns='urn:xmpp:sm:3'/>
2019-06-05 10:24:05.655 11425-12069/org.atalk.android D/SMACK: SENT (0): 
    <a xmlns='urn:xmpp:sm:3' h='30'/>
13

This topic was automatically closed 62 days after the last reply. New replies are no longer allowed.