Adds tests for quarkus.http.auth.form.new-cookie-interval #6013

Karm · 2019-12-08T01:06:16Z

There are three generally accepted behaviors for timeout and renewal for credential session cookies.

Quarkus implements 2. as timeout (quarkus.http.auth.form.timeout) and 3. as newCookieInterval (quarkus.http.auth.form.new-cookie-interval).

The implementation of 3. does not renew the cookie as expected.

The test does login, several requests and uses Thread.sleep(...); to pace them. I hope this is not deemed problematic for the stability of TS on very slow/weirdly behaving systems.
The margins are generous though, in hundreds of ms.

The test passes with the fixed calculation of cookie renewal and it fails with the current one:

org.opentest4j.AssertionFailedError:
   Session cookie WAS eligible for renewal and should have been updated.
at io.quarkus.vertx.http.security.FormAuthCookiesTestCase.
   testCredentialCookieRotation(FormAuthCookiesTestCase.java:183)

Thank you for feedback.

Fixes #6011

@sberyozkin @stuartwdouglas

...ttp/runtime/src/main/java/io/quarkus/vertx/http/runtime/security/PersistentLoginManager.java

Karm · 2019-12-09T08:36:45Z

@stuartwdouglas Changes to logging pushed. Thank you for review.

Karm · 2019-12-11T06:05:09Z

@stuartwdouglas @sberyozkin Hello, is there anything else I can do for this PR?

Karm · 2019-12-13T14:49:56Z

@stuartwdouglas @sberyozkin Hello, is there anything I can do to get this PR unstuck? Thx for letting me know. 🎱

stuartwdouglas · 2019-12-15T23:19:50Z

@Karm the new test failed on windows

Karm · 2019-12-16T09:33:33Z

@stuartwdouglas Lemme try on my Windows box and investigate. I will try to throttle down its I/O capacity to make sure the test passes on a feeble vm too.

Karm · 2019-12-18T13:32:14Z

I set up Jenkins CI on Windows 2012R2 and Centos7 to compare.

https://ci.modcluster.io/view/Quarkus/job/karm-quarkus/ (arbitrary GitHub login lets you in)

Windows fails with 5 tests in the vertx-http module with Graalvm11 and/or HotSpot11as its JDK. See /testReport

With Java 8, it is just 1 test that fails and it is this PR's one because @TestHTTPResource points to 0.0.0.0:8081 while in fact: Quarkus 999-SNAPSHOT started in 0.096s. Listening on: http://0.0.0.0:55230

See FormAuthCookiesTestCase/testCredentialCookieRotation

Not sure how to fix that now. Gonna look into it.

If @rsvoboda or @sberyozkin saw anything similar....

sberyozkin · 2020-01-14T13:34:21Z

@Karm Hi, can you please rebase and force a new build ? May be we will be able to merge soon

Karm · 2020-01-14T13:36:30Z

@sberyozkin I will, although I haven't really looked into how come that the RandomPort test apparently breaks this test of mine if you run them all...on Windows :-/

Lemme check again.

sberyozkin · 2020-01-14T21:59:20Z

Hey @Karm, I'm looking at the test code, and I wonder if it may be simplified somehow, I think it is very properly tested by the look of it, but I just suspect the test environment is not agile enough to cope with the ports recycling/etc

Karm · 2020-02-12T10:51:16Z

@sberyozkin, I went back to this one, logged output of what is going on in TestHTTPConfigSourceProvider and VertxHttpRecorder. The conclusion is that on Windows, all subsequent Quarkus deployments for all subsequent tests start with the port randomly generated for RandomPortTest deployment, e.g. 54320. The fix 0eabb66 is to clear env prop that is set in

 System.setProperty(launchMode == LaunchMode.TEST ? "quarkus.http.test-port" : "quarkus.http.port",
                                String.valueOf(actualPort));

in VertxHttpRecorder.

I have no idea why it does not show on Linux 😃

I executed it 10 times on my Windows box and the fix seems stable.

See the log:

Before `0eabb66`

Note 60748 is erroneously used in following tests.

[INFO] Running io.quarkus.vertx.http.RandomPortTest
Quarkus 999-SNAPSHOT started in 0.656s. Listening on: http://0.0.0.0:60748
Profile test activated.
Installed features: [cdi, security]
Quarkus stopped in 0.035s
[INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.622 s - in io.quarkus.vertx.http.RandomPortTest
[INFO] Running io.quarkus.vertx.http.router.RouterEventTest
Quarkus 999-SNAPSHOT started in 0.619s. Listening on: http://0.0.0.0:60748
Profile test activated.
Installed features: [cdi, security]
Quarkus stopped in 0.030s
[INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 2.455 s - in io.quarkus.vertx.http.router.RouterEventTest
[INFO] Running io.quarkus.vertx.http.security.DefaultDenyTestCase
Quarkus 999-SNAPSHOT started in 0.639s. Listening on: http://0.0.0.0:60748
Profile test activated.
Installed features: [cdi, security]
Quarkus stopped in 0.036s
[INFO] Tests run: 5, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 2.87 s - in io.quarkus.vertx.http.security.DefaultDenyTestCase
[INFO] Running io.quarkus.vertx.http.security.FormAuthCookiesTestCase
Quarkus 999-SNAPSHOT started in 0.649s. Listening on: http://0.0.0.0:60748
Profile test activated.
Installed features: [cdi, security]
Quarkus stopped in 0.034s
[ERROR] Tests run: 2, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 3.998 s <<< FAILURE! - in io.quarkus.vertx.http.security.FormAuthCookiesTestCase

After `0eabb66`

Note 59846 correctly followed by 8081.

[INFO] Running io.quarkus.vertx.http.RandomPortTest
Quarkus 999-SNAPSHOT started in 0.683s. Listening on: http://0.0.0.0:59846
Profile test activated.
Installed features: [cdi, security]
Quarkus stopped in 0.034s
[INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.87 s - in io.quarkus.vertx.http.RandomPortTest
[INFO] Running io.quarkus.vertx.http.router.RouterEventTest
Quarkus 999-SNAPSHOT started in 0.724s. Listening on: http://0.0.0.0:8081
Profile test activated.
Installed features: [cdi, security]
Quarkus stopped in 0.034s
[INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 2.659 s - in io.quarkus.vertx.http.router.RouterEventTest
[INFO] Running io.quarkus.vertx.http.security.DefaultDenyTestCase
Quarkus 999-SNAPSHOT started in 0.563s. Listening on: http://0.0.0.0:8081
Profile test activated.
Installed features: [cdi, security]
Quarkus stopped in 0.035s
[INFO] Tests run: 5, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 2.915 s - in io.quarkus.vertx.http.security.DefaultDenyTestCase

Karm · 2020-02-12T11:19:38Z

Azure pipeline failed with an inverted case:

2020-02-12 11:05:43,520 INFO  [io.quarkus] (main) Quarkus 999-SNAPSHOT started in 0.483s. Listening on: http://0.0.0.0:8081
2020-02-12 11:05:43,520 INFO  [io.quarkus] (main) Profile test activated. 
2020-02-12 11:05:43,522 INFO  [io.quarkus] (main) Installed features: [cdi, security]

org.apache.http.conn.HttpHostConnectException: Connect to 0.0.0.0:45537 [/0.0.0.0] failed: Connection refused (Connection refused)

Quarkus starts on a correct port, 8081, while TestHTTPConfigSourceProvider reports 45537.

I cannot reproduce this on my Windows VM with Java 11 though. I can see Azure running with Java 8, so lemme try that... 😢

stuartwdouglas · 2020-02-12T11:25:19Z

I attempted to address this here: https://github.com/quarkusio/quarkus/pull/7109/files#diff-ff552dc9ca707b4297c93a03adf556d6R644 although something else seems to have gone wrong with the pr, I will investigate tomorrow.

Karm · 2020-02-18T16:39:18Z

I have removed

   @AfterAll
    public static void teardown() {
        System.clearProperty("quarkus.http.test-port");
    }

from RandomPortTest.java as it is not needed since 7446beb is in now.

Karm · 2020-02-19T07:16:28Z

@stuartwdouglas With the latest commit it flawlessly passed two times already the point where it failed previously, i.e. no hiccup caused by RandomPortTest.

The reported failures in the current broader run are kinda weird build fails with Maven...totally unrelated:

[INFO] BUILD FAILURE
Could not retrieve code analysis results - Maven run failed.
[INFO] ------------------------------------------------------------------------
[INFO] Total time:  19:50 min
[INFO] Finished at: 2020-02-18T21:28:09Z
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal on project quarkus-jaeger: Could not resolve dependencies for project io.quarkus:quarkus-jaeger:jar:999-SNAPSHOT: The following artifacts could not be resolved: io.opentracing:opentracing-api:jar:0.31.0, io.opentracing:opentracing-util:jar:0.31.0, io.opentracing:opentracing-noop:jar:0.31.0, com.google.code.gson:gson:jar:2.8.2, io.jaegertracing:jaeger-thrift:jar:0.34.0, org.apache.thrift:libthrift:jar:0.12.0: Could not transfer artifact io.opentracing:opentracing-api:jar:0.31.0 from/to google-maven-central (https://maven-central-eu.storage-download.googleapis.com/repos/central/data/): maven-central-eu.storage-download.googleapis.com: Unknown host maven-central-eu.storage-download.googleapis.com -> [Help 1]
[ERROR] 
[ERROR] To see the full stack trace of the errors, re-run Maven with the -e switch.
[ERROR] Re-run Maven using the -X switch to enable full debug logging.
[ERROR] 
[ERROR] For more information about the errors and possible solutions, please read the following articles:
[ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/DependencyResolutionException
[ERROR] 
[ERROR] After correcting the problems, you can resume the build with the command
[ERROR]   mvn <args> -rf :quarkus-jaeger
Unable to get the FF: TestManagement.Server.EnablePublishToTcmServiceDirectlyFromTask. Reason: One or more errors occurred. (The HTTP request timed out after 00:05:00.)

Is there a way I could re-run just this part of the pipeline and not all the checks again?

Karm · 2020-02-19T09:19:00Z

It failed this time on a genuine test result; test added in this PR:

testCredentialCookieRotation

org.opentest4j.AssertionFailedError:
Session cookie WAS NOT eligible for renewal and should have remained the same. ==> 
expected: <DGKFWWL31VgE/jUh43qTCaHmeUTXu9aaCTrFujYI+NOeIVf8DtZw19FOPZVYqfVM>
but was: <DMu/i9NKzWJi2vUOYkO9BPp0BSVEPPF91xm/o9liUMfzqNZeLRaihjeJbq9Y9isr>

Despite the fact that the time spans in the test are lenient and worked well even on my slow Windows VM, it might not be enough for this CI.

I really hope that there are not multiple instances of Quarkus running and that the test is not talking to a different instance randomly 😃

I will make the time spans even more forgiving and watch the re-run.

Karm · 2020-02-19T21:00:20Z

artemis-core, artemis-jms, kafka, kafka-streams
##[error]The job running on agent Azure Pipelines 14 ran longer than the maximum time of 30 minutes.

Karm · 2020-02-19T21:23:57Z

artemis-core, artemis-jms, kafka, kafka-streams
View raw log

##[error]The job running on agent Azure Pipelines 14 ran longer than the maximum time of 30 minutes. For more information, see https://go.microsoft.com/fwlink/?linkid=2077134
Agent: Azure Pipelines 14
Started: Today at 3:40 PM
Duration: 29m 58s

@sberyozkin Could you restart just those two canceled ones, please? It seems I cannot do that.

Karm · 2020-02-20T07:27:26Z

...or perhaps @stuartwdouglas could push the button. I hope I won't see any more Artemis 30minutes timeout fails. Anyway, GitHub had some weird service degradation yesterday, so maybe that was related.

~~Plus 50bc77b needs review.~~

~~For the record: It passes on Windows 2019 dualcore feeble VM, it passes on octacore Fedora....locally.~~

Solved.

Karm · 2020-02-21T07:56:10Z

Hello, @gsmet, could you poke the CI and restart the seemingly pending checks, please?
It all timed-out on unrelated Maven builds and the one marked as failed is the artemis mvn > 30 minutes thingy.

~~Cheers~~

K.

Solved.

…terval There are three generally accepted behaviors for timeout and renewal for credential session cookies. 1. [absolute-timeout](https://cheatsheetseries.owasp.org/cheatsheets/Session_Management_Cheat_Sheet.html#absolute-timeout) 1. [idle-timeout]( https://cheatsheetseries.owasp.org/cheatsheets/Session_Management_Cheat_Sheet.html#idle-timeout) 1. [renewal-timeout](https://cheatsheetseries.owasp.org/cheatsheets/Session_Management_Cheat_Sheet.html#renewal-timeout) Quarkus implements 2. as **timeout** (```quarkus.http.auth.form.timeout```) and 3. as **newCookieInterval** (```quarkus.http.auth.form.new-cookie-interval```). The implementation of 3. does not renew the cookie as expected. The test does login, several requests and uses ```Thread.sleep(...);``` to pace them. I hope this is not deemed problematic for the stability of TS on very slow/weirdly behaving systems. The margins are generous though, in hundreds of ms. The test passes with the fixed calculation of cookie renewal and it fails with the current one: ``` org.opentest4j.AssertionFailedError: Session cookie WAS eligible for renewal and should have been updated. at io.quarkus.vertx.http.security.FormAuthCookiesTestCase. testCredentialCookieRotation(FormAuthCookiesTestCase.java:183) ``` Thank you for feedback. Concatenates log messages, drops level from warn to debug

sberyozkin · 2020-02-21T10:21:36Z

@Karm Thanks

Karm · 2020-02-21T11:58:44Z

@gsmet Could we have this merged then for 1.3?

stuartwdouglas requested changes Dec 8, 2019

View reviewed changes

...ttp/runtime/src/main/java/io/quarkus/vertx/http/runtime/security/PersistentLoginManager.java Outdated Show resolved Hide resolved

...ttp/runtime/src/main/java/io/quarkus/vertx/http/runtime/security/PersistentLoginManager.java Outdated Show resolved Hide resolved

Karm force-pushed the form-auth-cookie-rotation-test branch from 70954ed to 3c69461 Compare December 9, 2019 08:34

Karm requested a review from stuartwdouglas December 9, 2019 08:35

Karm force-pushed the form-auth-cookie-rotation-test branch from 3c69461 to 24225c1 Compare December 18, 2019 12:51

Karm force-pushed the form-auth-cookie-rotation-test branch from 24225c1 to 7662597 Compare February 11, 2020 15:26

boring-cyborg bot added the area/vertx label Feb 11, 2020

Karm requested a review from sberyozkin February 12, 2020 10:47

Karm force-pushed the form-auth-cookie-rotation-test branch from 6b80dcb to 7446beb Compare February 18, 2020 16:33

stuartwdouglas approved these changes Feb 19, 2020

View reviewed changes

stuartwdouglas added the triage/waiting-for-ci Ready to merge when CI successfully finishes label Feb 19, 2020

Karm force-pushed the form-auth-cookie-rotation-test branch from 7446beb to 50bc77b Compare February 19, 2020 10:39

Karm and others added 3 commits February 21, 2020 10:50

Pulls System.clearProperty from stuartwdouglas:graceful-shutdown

91e2d80

Tuning the timer for cookie renewal, should help on very slow VMs

08e0b81

Karm force-pushed the form-auth-cookie-rotation-test branch from 50bc77b to 08e0b81 Compare February 21, 2020 09:51

sberyozkin approved these changes Feb 21, 2020

View reviewed changes

stuartwdouglas merged commit 87b37c3 into quarkusio:master Feb 21, 2020

gsmet added this to the 1.3.0 milestone Feb 21, 2020

gsmet changed the title ~~Fixes 6011, adds tests for quarkus.http.auth.form.new-cookie-interval~~ Adds tests for quarkus.http.auth.form.new-cookie-interval Feb 21, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Adds tests for quarkus.http.auth.form.new-cookie-interval #6013

Adds tests for quarkus.http.auth.form.new-cookie-interval #6013

Karm commented Dec 8, 2019

Karm commented Dec 9, 2019

Karm commented Dec 11, 2019

Karm commented Dec 13, 2019

stuartwdouglas commented Dec 15, 2019

Karm commented Dec 16, 2019

Karm commented Dec 18, 2019 •

edited

Loading

sberyozkin commented Jan 14, 2020

Karm commented Jan 14, 2020 •

edited

Loading

sberyozkin commented Jan 14, 2020

Karm commented Feb 12, 2020

Karm commented Feb 12, 2020

stuartwdouglas commented Feb 12, 2020

Karm commented Feb 18, 2020

Karm commented Feb 19, 2020

Karm commented Feb 19, 2020

Karm commented Feb 19, 2020

Karm commented Feb 19, 2020

Karm commented Feb 20, 2020 •

edited

Loading

Karm commented Feb 21, 2020 •

edited

Loading

sberyozkin commented Feb 21, 2020

Karm commented Feb 21, 2020

Adds tests for quarkus.http.auth.form.new-cookie-interval #6013

Adds tests for quarkus.http.auth.form.new-cookie-interval #6013

Conversation

Karm commented Dec 8, 2019

Karm commented Dec 9, 2019

Karm commented Dec 11, 2019

Karm commented Dec 13, 2019

stuartwdouglas commented Dec 15, 2019

Karm commented Dec 16, 2019

Karm commented Dec 18, 2019 • edited Loading

sberyozkin commented Jan 14, 2020

Karm commented Jan 14, 2020 • edited Loading

sberyozkin commented Jan 14, 2020

Karm commented Feb 12, 2020

Before 0eabb66

After 0eabb66

Karm commented Feb 12, 2020

stuartwdouglas commented Feb 12, 2020

Karm commented Feb 18, 2020

Karm commented Feb 19, 2020

Karm commented Feb 19, 2020

Karm commented Feb 19, 2020

Karm commented Feb 19, 2020

Karm commented Feb 20, 2020 • edited Loading

Karm commented Feb 21, 2020 • edited Loading

sberyozkin commented Feb 21, 2020

Karm commented Feb 21, 2020

Karm commented Dec 18, 2019 •

edited

Loading

Karm commented Jan 14, 2020 •

edited

Loading

Before `0eabb66`

After `0eabb66`

Karm commented Feb 20, 2020 •

edited

Loading

Karm commented Feb 21, 2020 •

edited

Loading