Can't access course after Nutmeg upgrade, but also can't find useful error in logs

A student pointed out that they can no longer get to one of our old beta testing courses. I confirmed with my student account that I also see an error of “There was an error loading this course.”. However, the strange thing about this error vs. what I normally see is that I can’t find any meaningful error messages in the logs.

The first thing I did was check that there were no emojis in any section, subsection, or unit titles - and there aren’t. (Though I’m going to try that emoji fix shortly to see if it somehow magically solves this, but I wanted to post my error message before I make that change, just incase it’s different afterwards. Edit: The issue remains after doing the emoji fix.)

If I grep for the timestamp where I attempted to accessed the class as a student, I get the following:

ubuntu@ip-172-31-72-11:~$ tutor local logs --tail=1000 | grep -e '21:33:'
lms_1                        | 2022-08-07 21:33:04,719 INFO 19 [tracking] [user 7] [ip 1.2.3.4] logger.py:41 - {"name": "/api/course_home/outline/course-v1:MyOrg+MyClass+MyRun", "context": {"user_id": 7, "path": "/api/course_home/outline/course-v1:MyOrg+MyClass+MyRun", "course_id": "", "org_id": "", "enterprise_uuid": ""}, "username": "TestStudent", "session": "5591daf2b90fd84d67385f8b8a095dAA", "ip": "1.2.3.4", "agent": "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:103.0) Gecko/20100101 Firefox/103.0", "host": "my.site.com", "referer": "https://apps.my.site.com/", "accept_language": "en-US,en;q=0.5", "event": "{\"GET\": {}, \"POST\": {}}", "time": "2022-08-07T21:33:04.718832+00:00", "event_type": "/api/course_home/outline/course-v1:MyOrg+MyClass+MyRun", "event_source": "server", "page": null}
lms_1                        | 2022-08-07 21:33:04,719 INFO 7 [tracking] [user 7] [ip 1.2.3.4] logger.py:41 - {"name": "/theming/asset/images/logo.png", "context": {"user_id": 7, "path": "/theming/asset/images/logo.png", "course_id": "", "org_id": "", "enterprise_uuid": ""}, "username": "TestStudent", "session": "5591daf2b90fd84d67385f8b8a095dAA", "ip": "1.2.3.4", "agent": "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:103.0) Gecko/20100101 Firefox/103.0", "host": "my.site.com", "referer": "https://apps.my.site.com/", "accept_language": "en-US,en;q=0.5", "event": "{\"GET\": {}, \"POST\": {}}", "time": "2022-08-07T21:33:04.718965+00:00", "event_type": "/theming/asset/images/logo.png", "event_source": "server", "page": null}
lms_1                        | [pid: 7|app: 0|req: 22736/69940] 172.19.0.3 () {50 vars in 2966 bytes} [Sun Aug  7 21:33:04 2022] GET /theming/asset/images/logo.png => generated 0 bytes in 54 msecs (HTTP/1.1 302) 7 headers in 380 bytes (1 switches on core 0)
lms_1                        | 2022-08-07 21:33:04,778 INFO 7 [tracking] [user 7] [ip 1.2.3.4] logger.py:41 - {"name": "/api/course_home/course_metadata/course-v1:MyOrg+MyClass+MyRun", "context": {"user_id": 7, "path": "/api/course_home/course_metadata/course-v1:MyOrg+MyClass+MyRun", "course_id": "", "org_id": "", "enterprise_uuid": ""}, "username": "TestStudent", "session": "5591daf2b90fd84d67385f8b8a095dAA", "ip": "1.2.3.4", "agent": "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:103.0) Gecko/20100101 Firefox/103.0", "host": "my.site.com", "referer": "https://apps.my.site.com/", "accept_language": "en-US,en;q=0.5", "event": "{\"GET\": {\"browser_timezone\": [\"America/Los_Angeles\"]}, \"POST\": {}}", "time": "2022-08-07T21:33:04.778360+00:00", "event_type": "/api/course_home/course_metadata/course-v1:MyOrg+MyClass+MyRun", "event_source": "server", "page": null}
lms_1                        | [pid: 7|app: 0|req: 22737/69941] 172.19.0.3 () {54 vars in 3228 bytes} [Sun Aug  7 21:33:04 2022] GET /api/course_home/course_metadata/course-v1:MyOrg+MyClass+MyRun?browser_timezone=America%2FLos_Angeles => generated 23 bytes in 86 msecs (HTTP/1.1 404) 9 headers in 446 bytes (1 switches on core 0)
lms_1                        | 2022-08-07 21:33:04,994 INFO 7 [tracking] [user 7] [ip 1.2.3.4] logger.py:41 - {"name": "/theming/asset/images/favicon.ico", "context": {"user_id": 7, "path": "/theming/asset/images/favicon.ico", "course_id": "", "org_id": "", "enterprise_uuid": ""}, "username": "TestStudent", "session": "5591daf2b90fd84d67385f8b8a095dAA", "ip": "1.2.3.4", "agent": "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:103.0) Gecko/20100101 Firefox/103.0", "host": "my.site.com", "referer": "https://apps.my.site.com/", "accept_language": "en-US,en;q=0.5", "event": "{\"GET\": {}, \"POST\": {}}", "time": "2022-08-07T21:33:04.993753+00:00", "event_type": "/theming/asset/images/favicon.ico", "event_source": "server", "page": null}
lms_1                        | [pid: 7|app: 0|req: 22738/69942] 172.19.0.3 () {50 vars in 2972 bytes} [Sun Aug  7 21:33:04 2022] GET /theming/asset/images/favicon.ico => generated 0 bytes in 99 msecs (HTTP/1.1 302) 7 headers in 383 bytes (1 switches on core 0)
lms_1                        | 2022-08-07 21:33:05,349 INFO 19 [edx.certificate] [user 7] [ip 1.2.3.4] api.py:378 - Checking if student 7 has an invalidated certificate in course course-v1:MyOrg+MyClass+MyRun.
lms_1                        | 2022-08-07 21:33:05,358 INFO 19 [edx.certificate] [user 7] [ip 1.2.3.4] api.py:703 - Checking if student 7 is on the allowlist in course course-v1:MyOrg+MyClass+MyRun
lms_1                        | [pid: 19|app: 0|req: 22443/69943] 172.19.0.3 () {54 vars in 3135 bytes} [Sun Aug  7 21:33:04 2022] GET /api/course_home/outline/course-v1:MyOrg+MyClass+MyRun => generated 37426 bytes in 752 msecs (HTTP/1.1 200) 10 headers in 479 bytes (1 switches on core 0)
lms_1                        | [pid: 7|app: 0|req: 22739/69944] 172.19.0.3 () {50 vars in 896 bytes} [Sun Aug  7 21:33:44 2022] GET /asset-v1:MyOrg+MyClass+MyRun+type@asset+block@instructor.jpeg => generated 72255 bytes in 24 msecs (HTTP/1.1 200) 6 headers in 174 bytes (1 switches on core 0)
ubuntu@ip-172-31-72-11:~$ tutor local logs --tail=1000 | grep -e '21:34:'
lms_1                        | [pid: 19|app: 0|req: 22444/69945] 172.19.0.3 () {54 vars in 1139 bytes} [Sun Aug  7 21:34:54 2022] GET /asset-v1:MyOrg+MyClass+MyRun+type@asset+block@instructor.jpeg => generated 72255 bytes in 23 msecs (HTTP/1.1 200) 6 headers in 174 bytes (1 switches on core 0)

But even just not grepping specifically for those times and eyeballing the log or searching for “error” I can’t see anything around that time in the logs.

Does anyone have any ideas of what specifically to look for in the logs that could be correlated to a “There was an error loading this course.” error message displayed to students?

Hi,

Do you have hidden courses?

This error came out when I had them like this, due to mfe, so I changed them to about and it was resolved

Yes, it looks like the common thread is that courses set to “none” are no longer accessible to past students, whereas courses set to “about” are.

This seems like a bug, or at least change of behavior though. Did you make a thread discussing this on the forums previously, and if so can you point me at it?

I did make one, but I didn’t know how to document or explain it so they could verify it.

Thanks. I filed a github issue as Regis recommended on the Tutor forums.

1 Like