FWD » Core Development » Runtime Infrastructure

================================================================================================

PROPOSAL - [MAJOR] functional - WebClientProtocol.startKeepAlivePing

Inbound-only deadline: outbound activity no longer buys any tolerance

================================================================================================

REVIEW FINDING (abridged)

   "because the echo is emitted from the browser's onmessage handler, the deadline measures the

   client's inbound message-processing lag rather than its liveness - a page whose event loop is

   blocked [...] is declared 'gone or its page is no longer running' and closed. Outbound activity

   no longer buys any tolerance [...] Concrete blocker reachable from converted 4GL today:

   HTML-BROWSER:PRINT() [...] blocks the page task queue [...] a dialog left open past deadline +

   watchdog (~3.5 min at defaults) makes WatchdogTimer System.exit(-1) the client JVM and lose the

   FWD session and its record locks."

FILES

   src/com/goldencode/p2j/ui/client/driver/web/WebClientProtocol.java

   src/com/goldencode/p2j/ui/client/driver/web/PushMessagesWorker.java

------------------------------------------------------------------------------------------------

1. ROOT CAUSE

------------------------------------------------------------------------------------------------

Before r16675 a session survived on *either* direction of traffic. Jetty's EndPoint idle timeout is

reset by every successful write (SocketChannelEndPoint.flush() -> notIdle()), so a client the server

was still pushing output to was never reaped, no matter how long it had been silent.

r16675 replaces that with a strictly inbound deadline: lastDataNanos is stamped only from onMessage

(WebClientProtocol.java:463 and :478) and the tick closes the session when

(now - lastDataNanos) > dataIdleMs. The only thing that can refresh it is the page's own echo of

MSG_SERVER_PING, which is dispatched from the JS onmessage handler - i.e. from the page task queue.

Any page whose task queue is blocked therefore looks dead, even though its host, socket and JVM are

all healthy and the server's own writes are still completing normally.

The queue-depth grace does not cover it: PushMessagesWorker.sendMessage() polls the message off the

deque *before* writing (PushMessagesWorker.java:304), so getQueueSize() reads 0 while the write is

in flight, stuckTicks never engages, and teardown happens at the bare deadline.

------------------------------------------------------------------------------------------------

2. PROPOSED FIX

------------------------------------------------------------------------------------------------

Two changes, neither of which reintroduces the half-open-socket hole the heartbeat exists to close:

   (a) [this proposal] Let *outbound progress* postpone the deadline again, but as bounded evidence

       rather than as a full reset. Measure progress as "writes are still completing", which is

       exactly the signal Jetty's notIdle() used to give us, and which stops dead on a half-open

       socket (the write wedges and never completes).

   (b) [proposal-issue-major-functional-2] Derive the deadline from the configured idle tolerance

       instead of from the ping cadence. On the shipped configurations in this workspace that alone

       moves the print-dialog deadline from 90 s to 10 min (hotel_gui) or 1 h (counteract).

Both are needed. (b) makes the deadline honest about what the administrator configured; (a) makes a

busy-but-live peer survive it the way it did before this revision.

2.1 PushMessagesWorker: expose completed-write progress

--------------------------------------------------------

Add a monotonic counter of successfully transmitted messages. It is the outbound counterpart of

lastDataNanos and, unlike getQueueSize(), it is not blind to an in-flight write.

   /** Number of messages successfully handed to the socket, used as outbound liveness evidence. */

   private volatile long transmitted;

   /**

    * The number of messages successfully written to the socket since this worker started.

    * <p>

    * Used by the keep-alive timer as outbound evidence: a write completes when the frame has been

    * flushed to the peer's socket, which is the same signal that used to reset Jetty's idle

    * timeout, and it stops advancing on a half-open socket. Unlike {@link #getQueueSize} it is not

    * blind to a message which has already been polled off the queue but is still in flight.

    *

    * @return   The monotonically increasing count of transmitted messages.

    */

   public long getTransmittedCount()

   {

      return transmitted;

   }

and in sendMessage(Session), immediately after the existing failure check

(PushMessagesWorker.java:393-397):

            if (sendMessageException[0] != null)

            {

               msgSent = false;

               LOG.log(Level.WARNING, "Send message failed!", sendMessageException[0]);

            }

   +        else if (message != null)

   +        {

   +           // the frame reached the peer's socket; this is the outbound liveness evidence the

   +           // keep-alive timer uses, see getTransmittedCount

   +           transmitted++;

   +        }

The increment is single-writer (only the pushworker thread executes sendMessage), so a plain

volatile long is sufficient - no atomic needed.

2.2 WebClientProtocol: grant a grace while writes keep completing

------------------------------------------------------------------

Replace the queue-depth heuristic in the timer task with a test of that counter. The composed final

form of the tick is listed in proposal-issue-major-performance-1 (which owns the removal of the

queue-depth logic); the contribution of *this* proposal is the "progressing" branch:

   +  /** Transmitted count seen at the previous tick, used to detect completed outbound writes. */

   +  private long lastTransmitted;

      ...

   +           PushMessagesWorker worker = pushWorker;

   +           long transmitted = (worker != null) ? worker.getTransmittedCount() : 0L;

   +           boolean progressing = transmitted != lastTransmitted;

   +           lastTransmitted = transmitted;

   +

   +           long quietMs = (System.nanoTime() - lastDataNanos) / 1_000_000L;

   +

   +           // A peer that is still taking delivery is alive at the socket level even if its page

   +           // is not answering: its event loop may be blocked (a native print dialog from

   +           // HTML-BROWSER:PRINT, a modal file chooser) or it may simply be behind on a burst.

   +           // That is exactly the tolerance Jetty's idle timeout used to grant through notIdle(),

   +           // so it is granted here too - but bounded, because "the socket accepts bytes" is not

   +           // "the page runs code". See MAX_BACKLOG_GRACE_MULTIPLIER.

   +           if (quietMs > dataIdleMs && (!progressing || quietMs > graceLimitMs))

   +           {

   +              LOG.severe(...);

   +              session.close(SESSION_HEARTBEAT_LOST, "client heartbeat stopped", Callback.NOOP);

   +              return;

   +           }

Note the counter is sampled on *every* tick, not only when the deadline is exceeded; sampling only

inside the deadline branch would compare against a stale value from an arbitrarily long time ago and

make "progressing" trivially true.

2.3 Why the half-open case is still detected

---------------------------------------------

On the VPN-drop / laptop-suspend case the javadoc names, the socket send buffer stops draining and

the Jetty write callback never completes, so getTransmittedCount() freezes. The very first tick past

dataIdleMs then sees progressing == false and closes the session - the same behaviour as the code

being reviewed. The grace only ever applies while the kernel is still acknowledging our frames, and

even then it is capped (proposal-issue-minor-security-1).

------------------------------------------------------------------------------------------------

3. RELATIONSHIP TO OTHER PROPOSALS

------------------------------------------------------------------------------------------------

   proposal-issue-major-functional-2   deadline from the idle tolerance, not the ping cadence

                                       (prerequisite for a usable deadline on shipped configs)

   proposal-issue-major-performance-1  removes the queue-depth heuristic this replaces; owns the

                                       composed tick body and the priority push of the ping

   proposal-issue-minor-security-1     supplies graceLimitMs, the absolute cap on the grace granted

                                       here, and the worst-case-teardown javadoc

   proposal-issue-minor-functional-3   supplies SESSION_HEARTBEAT_LOST used in the close above

Applying 2.1 + 2.2 without proposal-issue-minor-security-1 would leave the grace unbounded; do not

land them separately.

------------------------------------------------------------------------------------------------

4. RISK AND VERIFICATION

------------------------------------------------------------------------------------------------

Risk: low. getTransmittedCount() is additive; the tick only ever gains a reason *not* to close.

Worst case a dead peer whose kernel still accepts small frames is reaped at graceLimitMs instead of

dataIdleMs - bounded, logged, and still far short of the TCP retransmission window this timer was

introduced to avoid.

Verification

   1. HTML-BROWSER:PRINT() from a converted procedure in the Web GUI; leave the native print dialog

      open for >3x pingPongInterval. Expected: session stays open, the keep-alive logs the grace at

      FINE, no WatchdogTimer System.exit(-1). Reproduces the reported blocker directly.

   2. Same test with the browser process SIGSTOPped instead (page blocked *and* socket unread):

      writes wedge, teardown occurs at dataIdleMs, i.e. dead-peer detection is unchanged.

   3. Drop the network at the OS level (VPN down / iptables DROP): teardown at dataIdleMs.

   4. Confirm the FINE grace log and the SEVERE teardown log both report quietMs, dataIdleMs and

      graceLimitMs, so a support engineer can tell the two apart.