-
Notifications
You must be signed in to change notification settings - Fork 2.7k
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Can't see debug logs in terminal #1354
Comments
I'm seeing DEBUG msgs in the console using this META-INF/microprofile-config.properties file: # Configuration file
mp.jwt.verify.publickey.location=META-INF/resources/publicKey.pem
mp.jwt.verify.issuer=https://quarkus.io/using-jwt-rbac
quarkus.smallrye-jwt.auth-mechanism=MP-JWT
quarkus.smallrye-jwt.enabled=true
# DEBUG console logging
quarkus.log.console.enable=true
quarkus.log.console.format=%d{HH:mm:ss} %-5p [%c{2.}]] (%t) %s%e%n
quarkus.log.console.level=DEBUG
# TRACE file logging
quarkus.log.file.enable=true
quarkus.log.file.path=/tmp/trace.log
quarkus.log.file.level=TRACE
quarkus.log.file.format=%d{HH:mm:ss} %-5p [%c{2.}]] (%t) %s%e%n
quarkus.log.category."io.quarkus.smallrye.jwt".level=TRACE
quarkus.log.category."io.undertow.request.security".level=TRACE
quarkus.log.category."io.smallrye.jwt".level=TRACE Example output: Scotts-iMacPro:using-jwt-rbac starksm$ java -jar target/using-jwt-rbac-1.0-SNAPSHOT-runner.jar
10:32:51 INFO [io.quarkus]] (main) Quarkus 999-SNAPSHOT started in 0.633s. Listening on: http://127.0.0.1:8080
10:32:51 INFO [io.quarkus]] (main) Installed features: [cdi, resteasy, resteasy-jsonb, security, smallrye-jwt]
10:33:13 DEBUG [io.un.re.security]] (XNIO-1 task-1) Attempting to authenticate /secured/permit-all, authentication required: false
10:33:13 DEBUG [io.un.re.security]] (XNIO-1 task-1) Authentication outcome was NOT_ATTEMPTED with method io.undertow.security.impl.CachedAuthenticatedSessionMechanism@760d4ee0 for /secured/permit-all
10:33:13 DEBUG [io.qu.sm.jw.ru.au.JwtIdentityManager]] (XNIO-1 task-1) verify, [email protected], credential=io.quarkus.smallrye.jwt.runtime.auth.JWTCredential@600219bd
10:33:13 DEBUG [io.sm.jw.co.JWTAuthContextInfoProvider]] (XNIO-1 task-1) init, mpJwtublicKey=NONE, mpJwtIssuer=https://quarkus.io/using-jwt-rbac, mpJwtLocation=META-INF/resources/publicKey.pem
10:33:13 DEBUG [io.sm.jw.co.JWTAuthContextInfoProvider]] (XNIO-1 task-1) init, mpJwtublicKey=NONE, mpJwtIssuer=https://quarkus.io/using-jwt-rbac, mpJwtLocation=META-INF/resources/publicKey.pem
10:33:13 DEBUG [io.sm.jw.au.pr.KeyLocationResolver]] (XNIO-1 task-1) Trying location as JWK(S)...
10:33:13 DEBUG [io.sm.jw.au.pr.KeyLocationResolver]] (XNIO-1 task-1) Failed to read location as JWK(S): javax.json.stream.JsonParsingException: JsonParser#getObject() or JsonParser#getObjectStream() is valid only for START_OBJECT parser state. But current parser state is VALUE_NUMBER
at org.glassfish.json.JsonReaderImpl.readObject(JsonReaderImpl.java:114)
at io.smallrye.jwt.auth.principal.KeyLocationResolver.tryAsJWKx(KeyLocationResolver.java:98)
at io.smallrye.jwt.auth.principal.KeyLocationResolver.resolveKey(KeyLocationResolver.java:68)
at org.jose4j.jwt.consumer.JwtConsumer.processContext(JwtConsumer.java:205)
at org.jose4j.jwt.consumer.JwtConsumer.process(JwtConsumer.java:416)
at io.quarkus.smallrye.jwt.runtime.auth.MpJwtValidator.validate(MpJwtValidator.java:84)
at io.quarkus.smallrye.jwt.runtime.auth.MpJwtValidator_ClientProxy.validate(Unknown Source)
at org.wildfly.security.auth.realm.token.TokenSecurityRealm$TokenRealmIdentity.validateToken(TokenSecurityRealm.java:207)
at org.wildfly.security.auth.realm.token.TokenSecurityRealm$TokenRealmIdentity.getClaims(TokenSecurityRealm.java:195)
at org.wildfly.security.auth.realm.token.TokenSecurityRealm$TokenRealmIdentity.exists(TokenSecurityRealm.java:157)
at org.wildfly.security.auth.realm.token.TokenSecurityRealm$TokenRealmIdentity.getEvidenceVerifySupport(TokenSecurityRealm.java:186)
at org.wildfly.security.auth.server.ServerAuthenticationContext$UnassignedState.verifyEvidence(ServerAuthenticationContext.java:1659)
at org.wildfly.security.auth.server.ServerAuthenticationContext$InactiveState.verifyEvidence(ServerAuthenticationContext.java:1391)
at org.wildfly.security.auth.server.ServerAuthenticationContext.verifyEvidence(ServerAuthenticationContext.java:759)
at org.wildfly.security.auth.server.SecurityDomain.authenticate(SecurityDomain.java:309)
at org.wildfly.security.auth.server.SecurityDomain.authenticate(SecurityDomain.java:270)
at io.quarkus.smallrye.jwt.runtime.auth.JwtIdentityManager.verify(JwtIdentityManager.java:39)
at io.quarkus.smallrye.jwt.runtime.auth.JWTAuthMechanism.authenticate(JWTAuthMechanism.java:67)
at io.undertow.security.impl.SecurityContextImpl$AuthAttempter.transition(SecurityContextImpl.java:245)
at io.undertow.security.impl.SecurityContextImpl$AuthAttempter.transition(SecurityContextImpl.java:268)
at io.undertow.security.impl.SecurityContextImpl$AuthAttempter.access$100(SecurityContextImpl.java:231)
at io.undertow.security.impl.SecurityContextImpl.attemptAuthentication(SecurityContextImpl.java:125)
at io.undertow.security.impl.SecurityContextImpl.authTransition(SecurityContextImpl.java:99)
at io.undertow.security.impl.SecurityContextImpl.authenticate(SecurityContextImpl.java:92)
at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:55)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46)
at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64)
at io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60)
at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77)
at io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:292)
at io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:81)
at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:138)
at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:135)
at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48)
at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
at io.quarkus.undertow.runtime.UndertowDeploymentTemplate$7$1$1.call(UndertowDeploymentTemplate.java:415)
at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:272)
at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:104)
at io.undertow.server.Connectors.executeRootHandler(Connectors.java:364)
at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:830)
at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1998)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1525)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1382)
at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.IllegalStateException: JsonParser#getObject() or JsonParser#getObjectStream() is valid only for START_OBJECT parser state. But current parser state is VALUE_NUMBER
at org.glassfish.json.JsonParserImpl.getObject(JsonParserImpl.java:171)
at org.glassfish.json.JsonReaderImpl.readObject(JsonReaderImpl.java:112)
... 49 more
10:33:13 DEBUG [io.qu.sm.jw.ru.au.JwtIdentityManager]] (XNIO-1 task-1) failed, [email protected], credential=io.quarkus.smallrye.jwt.runtime.auth.JWTCredential@600219bd: org.wildfly.security.auth.server.RealmUnavailableException: Failed to verify token
at io.quarkus.smallrye.jwt.runtime.auth.MpJwtValidator.validate(MpJwtValidator.java:113)
at io.quarkus.smallrye.jwt.runtime.auth.MpJwtValidator_ClientProxy.validate(Unknown Source)
at org.wildfly.security.auth.realm.token.TokenSecurityRealm$TokenRealmIdentity.validateToken(TokenSecurityRealm.java:207)
at org.wildfly.security.auth.realm.token.TokenSecurityRealm$TokenRealmIdentity.getClaims(TokenSecurityRealm.java:195)
at org.wildfly.security.auth.realm.token.TokenSecurityRealm$TokenRealmIdentity.exists(TokenSecurityRealm.java:157)
at org.wildfly.security.auth.realm.token.TokenSecurityRealm$TokenRealmIdentity.getEvidenceVerifySupport(TokenSecurityRealm.java:186)
at org.wildfly.security.auth.server.ServerAuthenticationContext$UnassignedState.verifyEvidence(ServerAuthenticationContext.java:1659)
at org.wildfly.security.auth.server.ServerAuthenticationContext$InactiveState.verifyEvidence(ServerAuthenticationContext.java:1391)
at org.wildfly.security.auth.server.ServerAuthenticationContext.verifyEvidence(ServerAuthenticationContext.java:759)
at org.wildfly.security.auth.server.SecurityDomain.authenticate(SecurityDomain.java:309)
at org.wildfly.security.auth.server.SecurityDomain.authenticate(SecurityDomain.java:270)
at io.quarkus.smallrye.jwt.runtime.auth.JwtIdentityManager.verify(JwtIdentityManager.java:39)
at io.quarkus.smallrye.jwt.runtime.auth.JWTAuthMechanism.authenticate(JWTAuthMechanism.java:67)
at io.undertow.security.impl.SecurityContextImpl$AuthAttempter.transition(SecurityContextImpl.java:245)
at io.undertow.security.impl.SecurityContextImpl$AuthAttempter.transition(SecurityContextImpl.java:268)
at io.undertow.security.impl.SecurityContextImpl$AuthAttempter.access$100(SecurityContextImpl.java:231)
at io.undertow.security.impl.SecurityContextImpl.attemptAuthentication(SecurityContextImpl.java:125)
at io.undertow.security.impl.SecurityContextImpl.authTransition(SecurityContextImpl.java:99)
at io.undertow.security.impl.SecurityContextImpl.authenticate(SecurityContextImpl.java:92)
at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:55)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46)
at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64)
at io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60)
at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77)
at io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:292)
at io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:81)
at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:138)
at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:135)
at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48)
at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
at io.quarkus.undertow.runtime.UndertowDeploymentTemplate$7$1$1.call(UndertowDeploymentTemplate.java:415)
at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:272)
at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:104)
at io.undertow.server.Connectors.executeRootHandler(Connectors.java:364)
at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:830)
at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1998)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1525)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1382)
at java.lang.Thread.run(Thread.java:748)
Caused by: org.jose4j.jwt.consumer.InvalidJwtException: JWT (claims->{"sub":"jdoe-using-jwt-rbac","aud":"using-jwt-rbac","upn":"[email protected]","birthdate":"2001-07-13","auth_time":1552029980,"iss":"https:\/\/quarkus.io\/using-jwt-rbac","roleMappings":{"group2":"Group2MappedRole","group1":"Group1MappedRole"},"groups":["Echoer","Tester","Subscriber","group2"],"preferred_username":"jdoe","exp":1552033580,"iat":1552029980,"jti":"a-123"}) rejected due to invalid claims. Additional details: [[1] The JWT is no longer valid - the evaluation time NumericDate{1552069993 -> Mar 8, 2019 10:33:13 AM PST} is on or after the Expiration Time (exp=NumericDate{1552033580 -> Mar 8, 2019 12:26:20 AM PST}) claim value (even when providing 60 seconds of leeway to account for clock skew).]
at org.jose4j.jwt.consumer.JwtConsumer.validate(JwtConsumer.java:449)
at org.jose4j.jwt.consumer.JwtConsumer.processContext(JwtConsumer.java:294)
at org.jose4j.jwt.consumer.JwtConsumer.process(JwtConsumer.java:416)
at io.quarkus.smallrye.jwt.runtime.auth.MpJwtValidator.validate(MpJwtValidator.java:84)
... 44 more
10:33:13 INFO [io.un.re.security]] (XNIO-1 task-1) Failed to authenticate JWT bearer token
10:33:13 DEBUG [io.un.re.security]] (XNIO-1 task-1) Authentication outcome was NOT_AUTHENTICATED with method io.quarkus.smallrye.jwt.runtime.auth.JWTAuthMechanism@6105923d for /secured/permit-all
10:33:13 DEBUG [io.un.re.security]] (XNIO-1 task-1) Sending authentication challenge for HttpServerExchange{ GET /secured/permit-all request {Accept=[*/*], Authorization=[Bearer eyJraWQiOiJcL3ByaXZhdGVLZXkucGVtIiwidHlwIjoiSldUIiwiYWxnIjoiUlMyNTYifQ.eyJzdWIiOiJqZG9lLXVzaW5nLWp3dC1yYmFjIiwiYXVkIjoidXNpbmctand0LXJiYWMiLCJ1cG4iOiJqZG9lQHF1YXJrdXMuaW8iLCJiaXJ0aGRhdGUiOiIyMDAxLTA3LTEzIiwiYXV0aF90aW1lIjoxNTUyMDI5OTgwLCJpc3MiOiJodHRwczpcL1wvcXVhcmt1cy5pb1wvdXNpbmctand0LXJiYWMiLCJyb2xlTWFwcGluZ3MiOnsiZ3JvdXAyIjoiR3JvdXAyTWFwcGVkUm9sZSIsImdyb3VwMSI6Ikdyb3VwMU1hcHBlZFJvbGUifSwiZ3JvdXBzIjpbIkVjaG9lciIsIlRlc3RlciIsIlN1YnNjcmliZXIiLCJncm91cDIiXSwicHJlZmVycmVkX3VzZXJuYW1lIjoiamRvZSIsImV4cCI6MTU1MjAzMzU4MCwiaWF0IjoxNTUyMDI5OTgwLCJqdGkiOiJhLTEyMyJ9.PAjjUKwiE19iSheB-2kBamW_u_r-tSyfyOfgne6OWwObiZmMrVygsbfO2SvVUABtF3eedjAKGcLXkpi1OAN7mamYIeTUP0D2v3YFVfoxJU7kqhIvXEfp7rDF44oj6My5ZfPLLQ--isUg0g9Ky5sdDJ53ggAg_B-6HQkdDCK2MBuA0KUqQ7-xxFYHvF_lRyOjivMsLpqrac_KlIfaJfIMe3K6l946sSKxUk55RN_MnunvFYYbBOZyAuHBoIGrhqnyK_JuiGqAsNX-NuBK8ImqcdlJ5lllrZiNl7ZcHoOLH7IehRA8MciIVyv8_2XQTlSFrvr_6pp0hGLKzVUOqvQfHw], User-Agent=[curl/7.54.0], Host=[localhost:8080]} response {}}
10:33:13 DEBUG [io.un.re.security]] (XNIO-1 task-1) Sending Bearer {token} challenge for HttpServerExchange{ GET /secured/permit-all request {Accept=[*/*], Authorization=[Bearer eyJraWQiOiJcL3ByaXZhdGVLZXkucGVtIiwidHlwIjoiSldUIiwiYWxnIjoiUlMyNTYifQ.eyJzdWIiOiJqZG9lLXVzaW5nLWp3dC1yYmFjIiwiYXVkIjoidXNpbmctand0LXJiYWMiLCJ1cG4iOiJqZG9lQHF1YXJrdXMuaW8iLCJiaXJ0aGRhdGUiOiIyMDAxLTA3LTEzIiwiYXV0aF90aW1lIjoxNTUyMDI5OTgwLCJpc3MiOiJodHRwczpcL1wvcXVhcmt1cy5pb1wvdXNpbmctand0LXJiYWMiLCJyb2xlTWFwcGluZ3MiOnsiZ3JvdXAyIjoiR3JvdXAyTWFwcGVkUm9sZSIsImdyb3VwMSI6Ikdyb3VwMU1hcHBlZFJvbGUifSwiZ3JvdXBzIjpbIkVjaG9lciIsIlRlc3RlciIsIlN1YnNjcmliZXIiLCJncm91cDIiXSwicHJlZmVycmVkX3VzZXJuYW1lIjoiamRvZSIsImV4cCI6MTU1MjAzMzU4MCwiaWF0IjoxNTUyMDI5OTgwLCJqdGkiOiJhLTEyMyJ9.PAjjUKwiE19iSheB-2kBamW_u_r-tSyfyOfgne6OWwObiZmMrVygsbfO2SvVUABtF3eedjAKGcLXkpi1OAN7mamYIeTUP0D2v3YFVfoxJU7kqhIvXEfp7rDF44oj6My5ZfPLLQ--isUg0g9Ky5sdDJ53ggAg_B-6HQkdDCK2MBuA0KUqQ7-xxFYHvF_lRyOjivMsLpqrac_KlIfaJfIMe3K6l946sSKxUk55RN_MnunvFYYbBOZyAuHBoIGrhqnyK_JuiGqAsNX-NuBK8ImqcdlJ5lllrZiNl7ZcHoOLH7IehRA8MciIVyv8_2XQTlSFrvr_6pp0hGLKzVUOqvQfHw], User-Agent=[curl/7.54.0], Host=[localhost:8080]} response {WWW-Authenticate=[Bearer {token}]}}
10:33:13 DEBUG [io.un.re.security]] (XNIO-1 task-1) Authentication result was CHALLENGE_SENT for /secured/permit-all |
I was using |
Using the microprofile properties file I can see the log messages as expected. My file:
Works as expected, same properties using command line, but with the properties file removed:
got only INFO Messages on console and file. Shouldn't the both options produce the same result? |
OK, now I understand the problem with my configuration... And it worked properly for both Perhaps the various minimum levels that come into play should be more clear, since that's what I hadn't noticed initially |
Ok maybe I´m dumb but I dont get it how to make it works I have my microprofile file with this content
And then in my code I´m using SLF4J
But still I cannot see the log in the console or quarkus.log in the target folder. Also in the /tmp/ there no debug.log Any idea what I´m doing wrong? |
Have you tried also setting |
something so silly like that thanks! |
I pulled the following configuration from the logging guide:
But when I apply it, I don't see any debug logs in the console, it's looks something like this:
Is there something wrong with example or is there a bug in Quarkus perhaps?
The text was updated successfully, but these errors were encountered: