Top

Spring Security 간헐적인 Login 에러

최근 작업하는 프로젝트에 Spring Security를 적용해서 개발하고 있다.

그런데 간헐적으로 로그인되지 않는 현상이 발생했다.

(프로그램에서 가장 잡기 어려운 버그가 랜덤하게 발생해서 재현 불가능한 버그다.)

 

톰캣을 재시작해도 로그인되지 않는 현상은 동일했으며, 컴퓨터를 재부팅하면 또 문제가 해결되었다.

 

1. 디버깅


재현이 불가능했기 때문에 해당 현상이 일어날 때 마다 조금씩 정보를 모았다.

 – 로그인 성공한 경우의 로그

11:13:06.468 seq[] user[] DEBUG org.springframework.security.web.context.HttpSessionSecurityContextRepository.saveContext (HttpSessionSecurityContextRepository.java:362) - SecurityContext 'org.springframework.security.core.context.SecurityContextImpl@fa4b76f4: Authentication: org.springframework.security.authentication.UsernamePasswordAuthenticationToken@fa4b76f4: Principal: GDto(gDtoReqType=null, regUserId=kaze, regDttm=2017-03-10 13:29:50.0, modUserId=null, modDttm=null, srchSrtDate=null, srchEndDate=null): UserId: kaze; Password: [PROTECTED]; Enabled: true; AccountNonExpired: true; credentialsNonExpired: true; AccountNonLocked: true; Granted Authorities: admin; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@957e: RemoteIpAddress: 127.0.0.1; SessionId: null; Granted Authorities: admin' stored to HttpSession: 'org.apache.catalina.session.StandardSessionFacade@5db9358a
11:13:06.469 seq[] user[] DEBUG drcs.common.security.handler.SignInSuccessHandler.onAuthenticationSuccess (SignInSuccessHandler.java:45) - response {"message":"로그인되었습니다.","error":false,"statusCode":200,"data":null}
11:13:09.142 seq[] user[] DEBUG org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter (SecurityContextPersistenceFilter.java:105) - SecurityContextHolder now cleared, as request processing completed
11:13:09.143 seq[] user[] DEBUG org.springframework.security.web.FilterChainProxy.doFilter (FilterChainProxy.java:324) - /checkAuthInfo at position 1 of 14 in additional filter chain; firing Filter: 'SecurityContextPersistenceFilter'
11:13:09.144 seq[] user[] DEBUG org.springframework.security.web.context.HttpSessionSecurityContextRepository.readSecurityContextFromSession (HttpSessionSecurityContextRepository.java:192) - Obtained a valid SecurityContext from SPRING_SECURITY_CONTEXT: 'org.springframework.security.core.context.SecurityContextImpl@fa4b76f4: Authentication: org.springframework.security.authentication.UsernamePasswordAuthenticationToken@fa4b76f4: Principal: GDto(gDtoReqType=null, regUserId=kaze, regDttm=2017-03-10 13:29:50.0, modUserId=null, modDttm=null, srchSrtDate=null, srchEndDate=null): UserId: kaze; Password: [PROTECTED]; Enabled: true; AccountNonExpired: true; credentialsNonExpired: true; AccountNonLocked: true; Granted Authorities: admin; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@957e: RemoteIpAddress: 127.0.0.1; SessionId: null; Granted Authorities: admin'
11:13:09.145 seq[] user[] DEBUG org.springframework.security.web.FilterChainProxy.doFilter (FilterChainProxy.java:324) - /checkAuthInfo at position 2 of 14 in additional filter chain; firing Filter: 'WebAsyncManagerIntegrationFilter'
11:13:09.145 seq[] user[] DEBUG org.springframework.security.web.FilterChainProxy.doFilter (FilterChainProxy.java:324) - /checkAuthInfo at position 3 of 14 in additional filter chain; firing Filter: 'HeaderWriterFilter'
11:13:09.146 seq[] user[] DEBUG org.springframework.security.web.header.writers.HstsHeaderWriter.writeHeaders (HstsHeaderWriter.java:128) - Not injecting HSTS header since it did not match the requestMatcher org.springframework.security.web.header.writers.HstsHeaderWriter$SecureRequestMatcher@5911817b
11:13:09.146 seq[] user[] DEBUG org.springframework.security.web.FilterChainProxy.doFilter (FilterChainProxy.java:324) - /checkAuthInfo at position 4 of 14 in additional filter chain; firing Filter: 'LogoutFilter'
11:13:09.147 seq[] user[] DEBUG org.springframework.security.web.util.matcher.AntPathRequestMatcher.matches (AntPathRequestMatcher.java:151) - Checking match of request : '/checkauthinfo'; against '/logout'
11:13:09.147 seq[] user[] DEBUG org.springframework.security.web.FilterChainProxy.doFilter (FilterChainProxy.java:324) - /checkAuthInfo at position 5 of 14 in additional filter chain; firing Filter: 'UsernamePasswordAuthenticationFilter'
11:13:09.148 seq[] user[] DEBUG org.springframework.security.web.util.matcher.AntPathRequestMatcher.matches (AntPathRequestMatcher.java:151) - Checking match of request : '/checkauthinfo'; against '/logincheck'
11:13:09.148 seq[] user[] DEBUG org.springframework.security.web.FilterChainProxy.doFilter (FilterChainProxy.java:324) - /checkAuthInfo at position 6 of 14 in additional filter chain; firing Filter: 'BasicAuthenticationFilter'
11:13:09.148 seq[] user[] DEBUG org.springframework.security.web.FilterChainProxy.doFilter (FilterChainProxy.java:324) - /checkAuthInfo at position 7 of 14 in additional filter chain; firing Filter: 'RequestCacheAwareFilter'
11:13:09.148 seq[] user[] DEBUG org.springframework.security.web.FilterChainProxy.doFilter (FilterChainProxy.java:324) - /checkAuthInfo at position 8 of 14 in additional filter chain; firing Filter: 'SecurityContextHolderAwareRequestFilter'
11:13:09.148 seq[] user[] DEBUG org.springframework.security.web.FilterChainProxy.doFilter (FilterChainProxy.java:324) - /checkAuthInfo at position 9 of 14 in additional filter chain; firing Filter: 'AnonymousAuthenticationFilter'
11:13:09.148 seq[] user[] DEBUG org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter (AnonymousAuthenticationFilter.java:106) - SecurityContextHolder not populated with anonymous token, as it already contained: 'org.springframework.security.authentication.UsernamePasswordAuthenticationToken@fa4b76f4: Principal: GDto(gDtoReqType=null, regUserId=kaze, regDttm=2017-03-10 13:29:50.0, modUserId=null, modDttm=null, srchSrtDate=null, srchEndDate=null): UserId: kaze; Password: [PROTECTED]; Enabled: true; AccountNonExpired: true; credentialsNonExpired: true; AccountNonLocked: true; Granted Authorities: admin; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@957e: RemoteIpAddress: 127.0.0.1; SessionId: null; Granted Authorities: admin'
11:13:09.148 seq[] user[] DEBUG org.springframework.security.web.FilterChainProxy.doFilter (FilterChainProxy.java:324) - /checkAuthInfo at position 10 of 14 in additional filter chain; firing Filter: 'SessionManagementFilter'
11:13:09.149 seq[] user[] DEBUG org.springframework.security.web.FilterChainProxy.doFilter (FilterChainProxy.java:324) - /checkAuthInfo at position 11 of 14 in additional filter chain; firing Filter: 'ExceptionTranslationFilter'
11:13:09.149 seq[] user[] DEBUG org.springframework.security.web.FilterChainProxy.doFilter (FilterChainProxy.java:324) - /checkAuthInfo at position 12 of 14 in additional filter chain; firing Filter: 'AjaxSessionCheckFilter'
11:13:09.149 seq[] user[] DEBUG org.springframework.security.web.FilterChainProxy.doFilter (FilterChainProxy.java:324) - /checkAuthInfo at position 13 of 14 in additional filter chain; firing Filter: 'FilterSecurityInterceptor'

 

 – 로그인 실패한 경우 로그

10:31:34.945 seq[] user[] DEBUG org.springframework.security.web.context.HttpSessionSecurityContextRepository.saveContext (HttpSessionSecurityContextRepository.java:362) - SecurityContext 'org.springframework.security.core.context.SecurityContextImpl@fa4b76f4: Authentication: org.springframework.security.authentication.UsernamePasswordAuthenticationToken@fa4b76f4: Principal: GDto(gDtoReqType=null, regUserId=kaze, regDttm=2017-03-10 13:29:50.0, modUserId=null, modDttm=null, srchSrtDate=null, srchEndDate=null): UserId: kaze; Password: [PROTECTED]; Enabled: true; AccountNonExpired: true; credentialsNonExpired: true; AccountNonLocked: true; Granted Authorities: admin; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@957e: RemoteIpAddress: 127.0.0.1; SessionId: null; Granted Authorities: admin' stored to HttpSession: 'org.apache.catalina.session.StandardSessionFacade@36946293
10:31:34.946 seq[] user[] DEBUG drcs.common.security.handler.SignInSuccessHandler.onAuthenticationSuccess (SignInSuccessHandler.java:45) - response {"message":"로그인되었습니다.","error":false,"statusCode":200,"data":null}
10:31:34.947 seq[] user[] DEBUG org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter (SecurityContextPersistenceFilter.java:105) - SecurityContextHolder now cleared, as request processing completed
10:31:34.953 seq[] user[] DEBUG org.springframework.security.web.FilterChainProxy.doFilter (FilterChainProxy.java:324) - /checkAuthInfo at position 1 of 14 in additional filter chain; firing Filter: 'SecurityContextPersistenceFilter'
10:31:34.953 seq[] user[] DEBUG org.springframework.security.web.context.HttpSessionSecurityContextRepository.readSecurityContextFromSession (HttpSessionSecurityContextRepository.java:159) - No HttpSession currently exists
10:31:34.953 seq[] user[] DEBUG org.springframework.security.web.context.HttpSessionSecurityContextRepository.loadContext (HttpSessionSecurityContextRepository.java:101) - No SecurityContext was available from the HttpSession: null. A new one will be created.
10:31:34.954 seq[] user[] DEBUG org.springframework.security.web.FilterChainProxy.doFilter (FilterChainProxy.java:324) - /checkAuthInfo at position 2 of 14 in additional filter chain; firing Filter: 'WebAsyncManagerIntegrationFilter'
10:31:34.954 seq[] user[] DEBUG org.springframework.security.web.FilterChainProxy.doFilter (FilterChainProxy.java:324) - /checkAuthInfo at position 3 of 14 in additional filter chain; firing Filter: 'HeaderWriterFilter'
10:31:34.954 seq[] user[] DEBUG org.springframework.security.web.header.writers.HstsHeaderWriter.writeHeaders (HstsHeaderWriter.java:128) - Not injecting HSTS header since it did not match the requestMatcher org.springframework.security.web.header.writers.HstsHeaderWriter$SecureRequestMatcher@4a10fd5e
10:31:34.954 seq[] user[] DEBUG org.springframework.security.web.FilterChainProxy.doFilter (FilterChainProxy.java:324) - /checkAuthInfo at position 4 of 14 in additional filter chain; firing Filter: 'LogoutFilter'
10:31:34.955 seq[] user[] DEBUG org.springframework.security.web.util.matcher.AntPathRequestMatcher.matches (AntPathRequestMatcher.java:151) - Checking match of request : '/checkauthinfo'; against '/logout'
10:31:34.955 seq[] user[] DEBUG org.springframework.security.web.FilterChainProxy.doFilter (FilterChainProxy.java:324) - /checkAuthInfo at position 5 of 14 in additional filter chain; firing Filter: 'UsernamePasswordAuthenticationFilter'
10:31:34.955 seq[] user[] DEBUG org.springframework.security.web.util.matcher.AntPathRequestMatcher.matches (AntPathRequestMatcher.java:151) - Checking match of request : '/checkauthinfo'; against '/logincheck'
10:31:34.955 seq[] user[] DEBUG org.springframework.security.web.FilterChainProxy.doFilter (FilterChainProxy.java:324) - /checkAuthInfo at position 6 of 14 in additional filter chain; firing Filter: 'BasicAuthenticationFilter'
10:31:34.955 seq[] user[] DEBUG org.springframework.security.web.FilterChainProxy.doFilter (FilterChainProxy.java:324) - /checkAuthInfo at position 7 of 14 in additional filter chain; firing Filter: 'RequestCacheAwareFilter'
10:31:34.956 seq[] user[] DEBUG org.springframework.security.web.FilterChainProxy.doFilter (FilterChainProxy.java:324) - /checkAuthInfo at position 8 of 14 in additional filter chain; firing Filter: 'SecurityContextHolderAwareRequestFilter'
10:31:34.956 seq[] user[] DEBUG org.springframework.security.web.FilterChainProxy.doFilter (FilterChainProxy.java:324) - /checkAuthInfo at position 9 of 14 in additional filter chain; firing Filter: 'AnonymousAuthenticationFilter'
10:31:34.956 seq[] user[] DEBUG org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter (AnonymousAuthenticationFilter.java:100) - Populated SecurityContextHolder with anonymous token: 'org.springframework.security.authentication.AnonymousAuthenticationToken@9055e4a6: Principal: anonymousUser; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@957e: RemoteIpAddress: 127.0.0.1; SessionId: null; Granted Authorities: ROLE_ANONYMOUS'
10:31:34.957 seq[] user[] DEBUG org.springframework.security.web.FilterChainProxy.doFilter (FilterChainProxy.java:324) - /checkAuthInfo at position 10 of 14 in additional filter chain; firing Filter: 'SessionManagementFilter'
10:31:34.957 seq[] user[] DEBUG org.springframework.security.web.FilterChainProxy.doFilter (FilterChainProxy.java:324) - /checkAuthInfo at position 11 of 14 in additional filter chain; firing Filter: 'ExceptionTranslationFilter'
10:31:34.957 seq[] user[] DEBUG org.springframework.security.web.FilterChainProxy.doFilter (FilterChainProxy.java:324) - /checkAuthInfo at position 12 of 14 in additional filter chain; firing Filter: 'AjaxSessionCheckFilter'
10:32:01.544 seq[] user[] DEBUG org.springframework.security.web.FilterChainProxy.doFilter (FilterChainProxy.java:324) - /checkAuthInfo at position 13 of 14 in additional filter chain; firing Filter: 'FilterSecurityInterc

 

위의 로그를 보면 로그인 성공한 경우는 SPRING_SECURITY_CONTEXT에서 valid한 SecurityContext를 얻었지만

실패한 경우는 “No SecurityContext was available from the HttpSession: null. A new one will be created.” 라고 하면서 새로운 HttpSession을 만드는 것을 볼 수 있다.

 

2. 원인 파악


내가 만든 프로젝트에서 스프링 시큐리티에 로그인 여부를 확인하는 부분이 조금 복잡하게 구성되어 있어서

처음에는 ajax를 통한 세션 체크가 비동기로 호출하면서 호출 순서가 뒤바껴서 발생되는 문제가 아닐까 생각했었다.

(로그인해서 세션이 생성되기도 전에 로그인 여부를 확인하는 로직이 돌아가서 로그인되지 않은 것으로 판단한다던지…)

 

하지만 확인해본 결과 호출 순서가 뒤엉키는 문제는 아니었다.

그래서 다른 부분을 확인하다가 jsessionid가 생성되었는지 확인해보라는 게시물을 보고 jsessionid를 확인해보니

이럴수가 로그인되지 않을때는 jsessionid가 쿠키에 저장되어 있지 않았다.

 

그리고 희한하게 크롬에서는 127.0.0.1로는 로그인되지 않지만, localhost로는 로그인되는 것을 확인했고

Internet Explorer에서는 127.0.0.1과 localhost 모두에서 정상적으로 로그인되는 것을 확인했다.

 

3. jsessionid를 생성하는지 확인

 


크롬에 개발자도구를 통해서 jsessionid를 설정하는 부분이 호출되는지 확인해본 결과 아래와 같이 로그인 될 때와 되지 않을 때 모두 jsessionid 설정을 요청하는 것을 확인 할 수 있었다.

 

 

이를 토대로 이런 일이 일어나는 것은 크롬에서 무언가가 잘못되고 있다고 판단했습니다.

생각해보니 제가 여러가지 프로젝트를 디버깅할 때 모두 127.0.0.1로 사용하고 그중에는 https//127.0.0.1과 같이 ssl로 서비스되는 프로젝트도 있었습니다.

아마도 크롬에서 127.0.0.1로 접속하면 이전에 접속한 정보를 캐싱해서 자동으로 https 접속이라고 생각해서 쿠키를 생성하는 것을 막지 않았나 생각됩니다.

 

4. 해결법


간단하게는 크롬 설정창에 가서 설정을 초기화 했더니 해당 현상이 해결되었습니다.

저와 같이 스프링 시큐리티를 설정했는데 알 수 없는 오류로 고생하시는 분들께 도움이 되었으면 좋겠네요

 

참고

크롬 쿠키 설정 문제에 관한 참고 문서

톰캣 세션 작동 원리

kaze

Test

No Comments

Post a Comment

This site uses Akismet to reduce spam. Learn how your comment data is processed.