WindowFuture often in strange state temporarily - while doing performance tests

[krasa]

https://github.com/krasa/cloudhopper-smpp/tree/bug
Start ServerMain and PerformanceClientMain

It happens quite often when SmppSession#submit is used. So I copypasted #sendRequestAndGetResponse and added some logging:

    ...
        // 3 possible scenarios once completed: success, failure, or cancellation
        final boolean success = future.isSuccess();
        final boolean cancelled = future.isCancelled();
        final boolean done = future.isDone();
        final PduResponse response = future.getResponse();
        final long doneTimestamp = future.getDoneTimestamp();
        if (success) {
            return future.getResponse();
        } else if (future.getCause() != null) {
            Throwable cause = future.getCause();
            if (cause instanceof ClosedChannelException) {
                throw new SmppChannelException("Channel was closed after sending request, but before receiving response", cause);
            } else {
                throw new UnrecoverablePduException(cause.getMessage(), cause);
            }
        } else {
            if (cancelled) {
                logger.error("{} {} {} {} {}", done, success, cancelled, doneTimestamp, response);
                logger.error("{} {} {} {} {}", future.isDone(), future.isSuccess(), future.isCancelled(), future.getDoneTimestamp(), future.getResponse());
                throw new RecoverablePduException("Request was cancelled");
            } else {
                logger.error("{} {} {} {} {}", done, success, cancelled, doneTimestamp, response);
                logger.error("{} {} {} {} {}", future.isDone(), future.isSuccess(), future.isCancelled(), future.getDoneTimestamp(), future.getResponse());
                throw new UnrecoverablePduException("Unable to sendRequestAndGetResponse successfully (future was in strange state)");
            }
        }

it produces:

PerformanceClientMain - true false false 1396892258272 (submit_sm_resp: 0x00000011 0x80000004 0x00000000 0x0000ADCA result: "OK") (body: (messageId [])) (opts: )
PerformanceClientMain - true true false 1396892258272 (submit_sm_resp: 0x00000011 0x80000004 0x00000000 0x0000ADCA result: "OK") (body: (messageId [])) (opts: )

PerformanceClientMain - true false true 0 null
PerformanceClientMain - true true false 1396892262655 (submit_sm_resp: 0x00000011 0x80000004 0x00000000 0x0000DE74 result: "OK") (body: (messageId [])) (opts: )

PerformanceClientMain - true false true 1396892295576 (submit_sm_resp: 0x00000011 0x80000004 0x00000000 0x00014F6D result: "OK") (body: (messageId [])) (opts: )
PerformanceClientMain - true true false 1396892295576 (submit_sm_resp: 0x00000011 0x80000004 0x00000000 0x00014F6D result: "OK") (body: (messageId [])) (opts: )

[jjlauer]

Garth will try to check this out tomorrow or Wed

[krasa]

Any news? It just happened to me in idle application, when only enquire link was running.

com.cloudhopper.smpp.type.UnrecoverablePduException: Unable to sendRequestAndGetResponse successfully (future was in strange state)
at com.cloudhopper.smpp.impl.DefaultSmppSession.sendRequestAndGetResponse(DefaultSmppSession.java:486)
at com.cloudhopper.smpp.impl.DefaultSmppSession.enquireLink(DefaultSmppSession.java:438)

[krasa]

@jjlauer I found it.

DefaultWindowFuture#completeHelper and #failedHelper are broken, because it sets #done before setting #response and #doneTimestamp. So DefaultWindowFuture#await which checks #done can return too soon.

This is how it should look like (logically, I do not suggest this particular fix):

        synchronized (done) {
            if (!this.done.get()) {
                this.response.set(response);
                this.doneTimestamp.set(doneTimestamp);
                this.done.set(true);
            }
        }

Since this problem does not concern real word uses, i guess it is fine to just leave it, and let users to add some artificial response delay - that's what I did.

[bandicoot86]

Up for the request. Under heavy load (3-5k/sec), I experience such an undesired behaviour.

[xgp]

ch-commons-util 6.0.2 with the fix for the race condition has been released. We will do a release of ch-smpp that forces this dependency on both the Netty 3 and 4 versions, but you should also be able to fix by forcing the version change in your project right away.

[xgp]

Fix released in 5.0.7. Promotion to Maven Central should be complete today.