How to debug the reason for authentication failure

[Tom Lancaster]

Hi,

I've broken my silhouette implementation somewhere along the road, and can no longer stay authenticated. I'm using the stateless Cookie Authenticator, and generating long authenticator cookie values. These cookies are being sent to ApplicationController.index() and rejected. I can't see any structural reason (domain, secure, path, cookie name) why. Is there any way to get more detail out of silhouette.SecuredAction.async as to why an authenticator is being rejected? 

I am using play-silhouette 4.0 and play 2.5.4, going from the play-silhouette seed, and incorporating slick.

Thanks,

[Christian Kaps]

Hi,

have you enabled logging for Silhouette?

http://silhouette.mohiva.com/docs/logging

Best regards,

Christian

[Tom Lancaster]

Yes, I have log levels set to debug:

<logger name="com.mohiva" level="DEBUG" />
<logger name="com.mohiva.play.silhouette.api.Silhouette" level="DEBUG" />
<logger name="utils.Logger" level="DEBUG"/>
<logger name="models.daos.OAuth2InfoDAO" level="DEBUG" />
<logger name="controllers.SocialAuthController" level="DEBUG" />
<logger name="models.services.AuthTokenService" level="DEBUG" />
<logger name="models.services.AuthTokenServiceImpl" level="DEBUG" />

Here is the request / response from Chrome:

1. Request URL:
   http://localhost:9000/
2. Request Method:
   GET
3. Status Code:
   303 See Other
4. Remote Address:
   [::1]:9000
1. Response Headersview source
1. Content-Length:
   0
2. Content-Security-Policy:
   default-src 'self'; img-src 'self' data: *.fbcdn.net *.twimg.com *.googleusercontent.com *.xingassets.com vk.com *.yimg.com secure.gravatar.com; style-src 'self' cdnjs.cloudflare.com maxcdn.bootstrapcdn.com cdn.jsdelivr.net fonts.googleapis.com; font-src 'self' fonts.gstatic.com fonts.googleapis.com cdnjs.cloudflare.com; script-src 'self' clef.io cdnjs.cloudflare.com; connect-src 'self' twitter.com *.xing.com; frame-src clef.io
3. Date:
   Thu, 08 Sep 2016 01:17:17 GMT
4. Location:
   /signIn
5. Set-Cookie:
   authenticator=; Max-Age=-86400; Expires=Wed, 07 Sep 2016 01:17:17 GMT; Path=/; Domain=localhost; HTTPOnly
6. X-Content-Type-Options:
   nosniff
7. X-Frame-Options:
   DENY
8. X-Permitted-Cross-Domain-Policies:
   master-only
9. X-XSS-Protection:
   1; mode=block
2. Request Headersview source
1. Accept:
   text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
2. Accept-Encoding:
   gzip, deflate, sdch
3. Accept-Language:
   en-US,en;q=0.8
4. Cache-Control:
   max-age=0
5. Connection:
   keep-alive
6. Cookie:
   PLAY_SESSION=9c709da9f5dd92848290ed705e100c13a9704c48-csrfToken=b554a60e0aca0b6646df782876757b15c0d4f2d5-1471959134814-18f7e38e1054d8f4492d749b; OAuth2State=1-6b4eac2f93d93c9a9455c5840b66df25020eda0e-eyJleHBpcmF0aW9uRGF0ZSI6MTQ3MzI5NzczNDI2OSwidmFsdWUiOiJhZWU2MjlkNWIyMjA5ZmQ5ZTFjM2EyZWIxYzFjNzFhNGU5YmQyYzkzMzRmZTk2MmFlNTUzM2Y3NmQzNzBiZTE0ZGU4OWM3MDdlZjllN2MzMTExMTIyZDUyNzQ5NGYyYTQyMzYwOTdjNTdlMjcwN2VkOGZmZTFmNWY3MjcwZmYyNDZhOGE5NjZmOTIwNGMyZmQ3MjI2ZWQwYTY3OTM2MzhjNTE0YWU3ZTBkNDM3Y2M0Y2Y0MmJiNzNmZjZkMmY3NTA1NDlmY2U1YzkyZGRmYWVjNTc2YjQ1ZTAzNDUzYWI5M2NmNDQ5ZDU5NTRiYTUyMWNlMTg1MDQ2YzY5YzVhZGExIn0=; authenticator=1-2b1f10a129d877c6e951db481c49cd9a53ad483a-1-HskpKtNAyFK8yu9MfCaqL2j084dOUQHMrTNYyb4ppHLXfNdQiTMqacfoA0mTVEmhFfv7AAg/Od58eEmWQTMRfBH3d5PjcHMCKiquZzZAcbrsEsYho2eDmNH5dmzb2JBdylaCb/Z0uNSYSDifkrnL2fIpSvoEV+uBpQ8jgY4LDwHXPL6XcLqWNKCko1+inGvLAUje7BMEWhrOeLFa4h8Ys71hY61rwWssI9GgpLmvltyk04z9MF6jxi6yMnWDfAxKNVBd+R/Q2Dxc/6gYc0rPkLZqVvs9NVZPEVuiI+zLl/SgjoCE7l9vEChONdgl7bwHBCyANhZOLUeYGAwm/1NeSX7nV6rU/sT6XzQTNnVRP0v+MEwLYduMbXSmvim7gTtB7jo0PJlMfMisiGOPVSPv5hxluKMESubvQsQS0BX33QC1PSDUdF+qckegukYOULMTow2bNAYiVq4vCD4sm1qg2vmHbe5LZsyeSvAgBsbDzGZAHM0Mfc+pOx31oePwLn4Ubbrezwa9OYkG5vYjaBf/BqyNKvHQgKDs0J6HaKWjv76NmYG22ka5WCa0yP+ezmZy9EXq0Szm1isFHC55eDfJZ0qyjG0QBtfBMehlv1nl5FE1FeqwA0WcDWoRL0VnstI0neO+U58+dC30ZcGpzyvrsoXXtQ==
7. Host:
   localhost:9000
8. Upgrade-Insecure-Requests:
   1
9. User-Agent:
   Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/52.0.2743.116 Safari/537.36
10. X-Client-Data:
    CIm2yQEIo7bJAQjEtskBCLCUygEI85zKAQ==

As you can see it's sending a 303 rather than a 401, which could be relevant.

[Christian Kaps]

I think the 303 comes from the fact that the seed template redirects to the login page. 

1. Set-Cookie:
   authenticator=; Max-Age=-86400; Expires=Wed, 07 Sep 2016 01:17:17 GMT; Path=/; Domain=localhost; HTTPOnly

This is a discarding cookie. So it seems that the discard method gets called. The SecuredAction calls discard if no user could be found for the LoginInfo stored in the authenticator.

Maybe this helps

[Tom Lancaster]

Yes, I think that is helpful. I've been refactoring various things in the data layer so it's conceivable I've broken something there. It's not clear to me from looking at this the path data would take from the database into this method, though. For example, where does 

handleAuthentication

Come from? Your help is much appreciated.

Tom

[Tom Lancaster]

The authentication cookie appears to contain a logininfo that has properly been persisted to the database, so if SecuredAction can't find it perhaps I didn't properly tell it how to?

CookieAuthenticator(*******,LoginInfo(google,100********),2016-09-07T21:17:17.384-04:00,2016-09-08T21:17:17.384-04:00,Some(1800000 milliseconds),None,Some(************))

[Tom Lancaster]

Christian, thanks again for the hint - I've tracked down the problem in my code to having renamed the primary key column in my user table to "userId"