Insights and Oauth2? Token error: Issued At claim (iat) cannot be in the future.

[Pierre Mailhot]

I've installed Insights on a separate server from the LMS/CMS. Everything works fine.

I've configured the Oauth2 stuff in /admin on the LMS.

I've configured local.py in Insights Dashboard settings.

I see Insights going to my login page on the LMS. I enter my credentials.

I see in the LMS logs that I have been successfully authenticated.

Nonetheless, I am not redirected back to Insights (/complete/edx-oidc as per https://github.com/edx/edx-analytics-dashboard/wiki/WIP:-OpenID-Connect).

Both my servers are time synchronized through NTP, but I do get these weird error messages:

Token error: Issued At claim (iat) cannot be in the future.

Any ideas what is going wrong here? Any suggestions on how to fix this? Is it a time synchronization issue? What do I need to fix?

Thanks in advance for any tips or suggestions.

Here's the traceback from the Analytics Dashboard:

2015-05-13 18:04:57,545 ERROR 2587 [django.request] base.py:231 - Internal Server Error: /complete/edx-oidc/

Traceback (most recent call last):

  File "/home/ubuntu/.venvs/edx-analytics-dashboard/local/lib/python2.7/site-packages/django/core/handlers/base.py", line 111, in get_response

    response = wrapped_callback(request, *callback_args, **callback_kwargs)

  File "/home/ubuntu/.venvs/edx-analytics-dashboard/local/lib/python2.7/site-packages/django/views/decorators/cache.py", line 52, in _wrapped_view_func

    response = view_func(request, *args, **kwargs)

  File "/home/ubuntu/.venvs/edx-analytics-dashboard/local/lib/python2.7/site-packages/django/views/decorators/csrf.py", line 57, in wrapped_view

    return view_func(*args, **kwargs)

  File "/home/ubuntu/.venvs/edx-analytics-dashboard/local/lib/python2.7/site-packages/social/apps/django_app/utils.py", line 52, in wrapper

    return func(request, backend, *args, **kwargs)

  File "/home/ubuntu/.venvs/edx-analytics-dashboard/local/lib/python2.7/site-packages/social/apps/django_app/views.py", line 28, in complete

    redirect_name=REDIRECT_FIELD_NAME, *args, **kwargs)

  File "/home/ubuntu/.venvs/edx-analytics-dashboard/local/lib/python2.7/site-packages/social/actions.py", line 40, in do_complete

    user = backend.complete(user=user, *args, **kwargs)

  File "/home/ubuntu/.venvs/edx-analytics-dashboard/local/lib/python2.7/site-packages/social/backends/base.py", line 40, in complete

    return self.auth_complete(*args, **kwargs)

  File "/home/ubuntu/.venvs/edx-analytics-dashboard/local/lib/python2.7/site-packages/auth_backends/backends.py", line 58, in auth_complete

    user = super(EdXOpenIdConnect, self).auth_complete(*args, **kwargs)

  File "/home/ubuntu/.venvs/edx-analytics-dashboard/local/lib/python2.7/site-packages/social/backends/oauth.py", line 368, in auth_complete

    method=self.ACCESS_TOKEN_METHOD

  File "/home/ubuntu/.venvs/edx-analytics-dashboard/local/lib/python2.7/site-packages/social/backends/open_id.py", line 361, in request_access_token

    self.id_token = self.validate_and_return_id_token(response['id_token'])

  File "/home/ubuntu/.venvs/edx-analytics-dashboard/local/lib/python2.7/site-packages/social/backends/open_id.py", line 336, in validate_and_return_id_token

    raise AuthTokenError(self, err)

AuthTokenError: Token error: Issued At claim (iat) cannot be in the future.

[13/May/2015 18:04:57] "GET /complete/edx-oidc/?state=u4kaQoW7VJK3uYxWdORH6Ihma88RPkui&code=7fdfc0e217217b29557b59369832477da3fc0cc1 HTTP/1.1" 500 136431

[Pierre Mailhot]

Still can't figure that one. If I access the LMS in the same browser after the error, I do have access to a session, therefore it proves the authentication was correct. Could there be a problem in creating the AuthToken before returning control to Insights through the URI? 

I am using Birch and the standard OAuth2 service that came with it.

[Sukla Nag]

I too got the same error & while searching net for the error I hit on your post.

I tried & resolved the problem. So in case you have not solved it yet, here is the solution

The problem is coming because of the time difference betrween the machines. So the check on time has to be disabled in the jwt decode which is in the file
.venvs/edx-analytics-dashboard/local/lib/python2.7/site-packages/social/backends/open_id.py
 Change the line id_token = jwt_decode(id_token, decryption_key, audience=client_id,
                                  issuer=self.ID_TOKEN_ISSUER,algorithms=['HS256'])
to
id_token = jwt_decode(id_token, decryption_key, audience=client_id,
                                  issuer=self.ID_TOKEN_ISSUER,options = {'verify_iat': False,},
                                  algorithms=['HS256']) & it will work.

[Pierre Mailhot]

Thanks for you message. I thought ntp was installed and configured on my servers, but it turns out it wasn't. I solved the problem by making sure ntp was configured and running properly. I simply forgot to write back and explain what I did to solve the issue.

--
You received this message because you are subscribed to a topic in the Google Groups "Open edX operations" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/openedx-ops/rcda7xp7s1c/unsubscribe.
To unsubscribe from this group and all its topics, send an email to openedx-ops...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/openedx-ops/d9663c2a-11d8-4c96-9718-5dbe5d417c31%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--

Salutations / Regards ,

Pierre Mailhot, M.Sc., CISSP, CEH

514-916-9558

[Zachary Trabookis]

Jason,

We're getting the same error above (https://gist.github.com/ztraboo/3b671f57487708d80ed1).  Here is our setup.  I was trying to follow https://github.com/edx/edx-analytics-pipeline/wiki/Configuring-Insights-for-Open-ID-Connect-SSO-with-LMS.

Both servers below are synced to the same ntp serviers.  I ran this command and both look the same.  Plus issuing date resulted in Thu Nov 12 22:29:28 EST 2015 for both servers.

ntpq -c lpeer

Insights Server

 /edx/etc/insights.yml

---

# This file is created and updated by ansible, edit at your peril

APPLICATION_NAME: Insights

CACHES:

    default:

        BACKEND: django.core.cache.backends.memcached.MemcachedCache

        KEY_PREFIX: default_env-default_deployment-insights

        LOCATION:

        - 127.0.0.1:11211

COURSE_API_URL: https://domain.com/api/course_structure/v0/

CSRF_COOKIE_NAME: insights_csrftoken

DATABASES:

    default:

        ENGINE: django.db.backends.mysql

        HOST: 127.0.0.1

        NAME: dashboard

        PASSWORD: secret

        PORT: '3306'

        USER: rosencrantz

DATABASE_OPTIONS:

    connect_timeout: 10

DATA_API_AUTH_TOKEN: changeme

DATA_API_URL: http://127.0.0.1:8100/api/v0

DOCUMENTATION_LOAD_ERROR_URL: http://127.0.0.1/en/latest/Reference.html#error-conditions

EMAIL_HOST: smtp.example.com

EMAIL_HOST_PASSWORD: mail_password

EMAIL_HOST_USER: mail_user

EMAIL_PORT: 587

ENABLE_AUTO_AUTH: false

FEEDBACK_EMAIL: dash...@example.com

HELP_URL: http://127.0.0.1/en/latest

INSIGHTS_OAUTH2_SECRET: OAUTH_SECRET

INSIGHTS_OAUTH2_URL_ROOT: https://domain.com/oauth2

INSIGHTS_OAUTH2_KEY: OAUTH_KEY

INSIGHTS_TIME_ZONE: 'America/New_York'

LANGUAGE_CODE: en-us

LANGUAGE_COOKIE_NAME: insights_language

LMS_COURSE_SHORTCUT_BASE_URL: URL_FOR_LMS_COURSE_LIST_PAGE

MODULE_PREVIEW_URL: https://domain.com/xblock

OPEN_SOURCE_URL: http://set-me-please

PLATFORM_NAME: edX

PRIVACY_POLICY_URL: http://example.com/privacy-policy

RESEARCH_URL: https://www.edx.org/research-pedagogy

SECRET_KEY: YOUR_SECRET_KEY_HERE

SEGMENT_IGNORE_EMAIL_REGEX: null

SEGMENT_IO_KEY: YOUR_KEY

SESSION_COOKIE_NAME: insights_sessionid

SOCIAL_AUTH_EDX_OIDC_ID_TOKEN_DECRYPTION_KEY: OAUTH_SECRET

SOCIAL_AUTH_EDX_OIDC_KEY: OAUTH_KEY

SOCIAL_AUTH_EDX_OIDC_SECRET: OAUTH_SECRET

SOCIAL_AUTH_EDX_OIDC_URL_ROOT: https://domain.com/oauth2

SOCIAL_AUTH_REDIRECT_IS_HTTPS: true

STATICFILES_DIRS:

- /edx/app/insights/edx_analytics_dashboard/analytics_dashboard/static

STATIC_ROOT: /edx/var/insights/staticfiles

SUPPORT_EMAIL: ''

SUPPORT_URL: ''

TERMS_OF_SERVICE_URL: http://example.com/terms-service

THEME_SCSS: sass/themes/open-edx.scss

TIME_ZONE: 'America/New_York'

LMS Server

/edx/app/edxapp/lms.env.json

"FEATURES": {

        "ENABLE_OAUTH2_PROVIDER": true,
}

"OAUTH_ENFORCE_SECURE": true, 

"OAUTH_OIDC_ISSUER": "https://domain.com/oauth2", 

https://github.com/edx/edx-platform/blob/named-release/cypress/lms/envs/aws.py#L563-L567

Do I need to enable OAUTH_ENFORCE_CLIENT_SECURE?

We are receiving a HTTP 500 error with after LMS login from redirect from our insights home page ("Login" button click).

  File "/edx/app/insights/venvs/insights/local/lib/python2.7/site-packages/social/backends/open_id.py", line 336, in validate_and_return_id_token

    raise AuthTokenError(self, err)

AuthTokenError: Token error: Issued At claim (iat) cannot be in the future.

 Zach

[Clinton Blackburn]

This message indicates the clocks are out of sync. Make sure both servers/VMs/etc. are syncing to the same time server.

I use the following script when I have issues with clock skew between my devstack and locally-hosted services. Add the lines below to a .sh file (e.g. update-time.sh) and run with sudo.

service ntp stop

ntpdate time.nist.gov

service ntp start

date

[Zachary Trabookis]

Clinton,

Thanks for the reply.  Here are the outputs to both servers for ntpq -c lpeer and date commands.  Don't these look correct?

Insights Server

ntpq -c lpeer
     remote           refid      st t when poll reach   delay   offset  jitter

==============================================================================

+odin.ces.clemso 204.2.134.163    3 u   52 1024  377    0.577    1.208   1.466

*ruby.ces.clemso 108.61.73.244    3 u  534 1024  377    0.468   -2.238   1.298

date

Fri Nov 13 10:08:23 EST 2015

LMS Server

ntpq -c lpeer
     remote           refid      st t when poll reach   delay   offset  jitter

==============================================================================

 odin.ces.clemso 108.61.56.35     3 -  52d   64    0    1.601    2.498   0.000

 ruby.ces.clemso 198.60.22.240    2 -  52d   64    0    0.902   -0.383   0.000

date
Fri Nov 13 10:08:59 EST 2015

[Zachary Trabookis]

Clinton,

We think the ntp timeservers are configuring the time for the Insights and LMS servers appropriately.

Could this be a configuration issue with OAUTH on the LMS?

https://github.com/edx/edx-platform/blob/named-release/cypress/lms/envs/aws.py#L563-L567

See my configuration above in 

https://groups.google.com/d/msg/openedx-ops/rcda7xp7s1c/NQcR8AD-EgAJ

We're basing our configuration on these two articles:

https://github.com/edx/edx-analytics-pipeline/wiki/Configuring-Insights-for-Open-ID-Connect-SSO-with-LMS

https://github.com/edx/edx-analytics-dashboard/wiki/WIP:-OpenID-Connect

Zach

[Clinton Blackburn]

Neither the LMS nor Insights settings control the time on your machines. Were you able to actually run the script I sent? Looking at the ntpq output you provided, your LMS server has not polled a timeserver in 52 days. Your clocks are definitely not synced. If you sync your clocks, this problem will be resolved.

Clinton Blackburn

[Zachary Trabookis]

Clinton,

Thanks for catching that. We'll look into the LMS server's time and let you know if that resolves this error.

Zach

[Zachary Trabookis]

Clinton,

We reset ntp server for the LMS and had to reboot that server to get the time synced (out of the 52 days of not syncing).  After that it resolved our login error above.  We can now view the Insights dashboard page after LMS authentication has occurred.  Thanks for the help.  We used the same ntp server list and did not add the time.nist.gov server.  We are not sure why the ntp server was out of sync for 52 days but will continue to monitor that service to see why.  

Insights Server

ntpq -c lpeer

     remote           refid      st t when poll reach   delay   offset  jitter

==============================================================================

+odin.ces.clemso 209.208.79.69    3 u   41  128  377    0.476    5.412   0.521

*ruby.ces.clemso 108.61.73.244    3 u  124  128  377    0.293   -1.957   0.235

date

Mon Nov 16 09:23:41 EST 2015

LMS Server

ntpq -c lpeer

     remote           refid      st t when poll reach   delay   offset  jitter

==============================================================================

+odin.ces.clemso 209.208.79.69    3 u  111  128  377    0.534    2.210   0.763

*ruby.ces.clemso 108.61.73.244    3 u   31  128  377    0.482   -6.804   1.685

date

Mon Nov 16 09:23:44 EST 2015

[Daniel Jaramillo]

Hello Zachary Trabookis.
You could tell me, how to reset ntp server to resolve the problem?
Please help me!!!.

[Juan Jose Miranda]

Use this:
sudo service ntp stop
sudo ntpdate time.nist.gov
sudo service ntp start

JJMiranda