search

RoboTutorLLC / RoboTutor_2020

Other
3 stars 1 forks source link

Bug report: 3.5.0.1 gray screen #120

Open JackMostow opened 2 years ago

JackMostow commented 2 years ago

Describe the bug A clear and concise description of what the bug is. RoboTutor displays all gray screen (except for green banner at top?)

To Reproduce Steps to reproduce the behavior:

  1. Pick activity from activities menu

Expected behavior A clear and concise description of what you expected to happen. Chosen activity should start and operate normally.

Actual behavior A clear and concise description of how the code performed w.r.t expectations. RoboTutor displays gray screen instead except for green banner at top (?) Screenshots If applicable, add screenshots to help explain your problem.

Additional details Suspect missing assets due to incomplete installation of assets. Need way to check if all assets installed.

RTBagamoyo commented 2 years ago

They look like this:

image

RTBagamoyo commented 2 years ago

story.echo::vow.A..Z.asc.lc.6__it.vfftffft2fffra3641

The only 2022/10/19 logs I found from 6111000161 were [PERF_]:

RoboTutor_fftffft2fffra3641_3.5.0.1_000068_2022.10.19.12.04.52_6111000161.json. It started at 12:04 -- after the bug report -- and does not contain "vow.A..Z.asc.lc.6".

RTBagamoyo commented 2 years ago

story.echo::vow.A..Z.asc.lc.6__it_4.vfftffft2fffra3641

When I searched RoboTutor logs for logs from 6109000572 and searched the page for "2022.10.24", GDrive didn't find any -- but when I searched by hand, I found:

RoboTutor_fftffft2fffra3641_3.5.0.1_000233_2022.10.24.11.18.11_6109000572.json

which ends ~3 minutes later at line 3066: {"class":"VERBOSE","tag":"RTag","type":"TimeStamp","datetime":"10/24/2022 11:30:59","time":"1666600259956","data":{"RoboTutor":"SessionEnd"}},

Unfortunately, searching for 1666600259956 doesn't find line 3066, either when just displayed or in texteditor.co :<). But it does find "1666600259956. Go figure!

The next step is to look for where activity story.echo::vow.A..Z.asc.lc.6__it_4.vfftffft2fffra3641 is selected. Searching for story.echo::vow.A..Z.asc.lc.6__it_4.vfftffft2fffra3641 doesn't work, but that doesn't necessarily mean it's not there.

We know that 10/24/2022 11:30:59 = 1666600259956. So 3 minutes earlier = 3 60 sec/min 1000 ms/sec = 180000 ms earlier. 1666600259956 - 180000 = 1,666,600,079,956. The nearest logged event is: 2323: {"type":"LOG_DATA","tutor":"activity_selector","class":"INFO","tag":"RQTag","time":"1666600079158","data":{"target":"node.audio","action":"play","name":"What would you like to do"}},

2554: {"type":"LOG_DATA","tutor":"story.echo::vow.A..Z.asc.lc.6__it_4","class":"INFO","tag":"RTag","time":"1666600122450","data":{"target":"ctutor","action":"create","tutorname":"story_reading"}},

So what happened next -- in particular, any signs of errors?

2558: {"type":"LOG_DATA","tutor":"story.echo::vow.A..Z.asc.lc.6__it_4","class":"INFO","tag":"RTag","time":"1666600122524","data":{"target":"ctutorgraph","action":"preenterscene","setdatasource":"[sharedliteracy]vow.A..Z.asc.lc.6"}},

2559: {"class":"ERROR","tag":"CRt_Component","type":"Exception","time":"1666600123359","msg":"Story Parse Error: ","exception":"org.json.JSONException: End of input at character 0 of "},

[ ] So we should find vow.A..Z.asc.lc.6 and check it for syntax errors, or possibly for bugs in the parser

12/14/2022: But where the hell is story.echo::vow.A..Z.asc.lc.6__it_4? Search in RoboTutorLLC/RoboTutor_2020/find/development for story.echo::vow.A..Z.asc.lc.6__it_4

Wrong branch? Wrong repo?

Options:

  1. Find story.echo::vow.A..Z.asc.lc.6__it_4 a. robotutor_2020 -: storydata.json files are only in docs/debugLauncher b. RTAsset_Publisher -: has storydata.json only for actual stories, not literacy exercises c. TransitionTableGenerator -: no storydata.json d. ?
  2. robotutor_2019 -: even fewer storydata.json
  3. Look on tablet a. robotutor_assets -: not found ?: hidden? FINALLY found on tablet in Documents > robotutor_assets > assets > story > sw > literacy > vow.A..Z.asc.lc.6 > storydata.json, which parses ok as JSON. NEXT: search source code for parse error message: "Story Parse Error: ","exception":"org.json.JSONException: End of input at character 0 of "
  4. Look in GDrive
  5. Look in .zip files
  6. Find where RoboTutor loads storydata.json from
  7. Look for same error in other log files

2560: {"class":"ERROR","tag":"TRtComponent","type":"Exception","time":"1666600123982","msg":"Invalid Data Source for : story_reading","exception":"java.lang.NullPointerException: Attempt to read from null array"},

... 2565: {"type":"LOG_DATA","tutor":"story.echo::vow.A..Z.asc.lc.6__it_4","class":"INFO","tag":"RTag","time":"1666600124310","data":{"target":"node.audio","action":"play","name":"Please read aloud"}},

2566: {"type":"LOG_DATA","tutor":"story.echo::vow.A..Z.asc.lc.6__it_4","class":"INFO","tag":"RTag","time":"1666600124310","data":{"target":"node.module","name":"INTRO_STATE","event":"end","modulestate":"WAIT"}},

2567: {"type":"LOG_DATA","tutor":"story.echo::vow.A..Z.asc.lc.6__it_4","class":"INFO","tag":"RTag","time":"1666600124310","data":{"target":"node.scenegraph.applyNode","name":"INTRO_STATE","end State":"WAIT"}},

1956 ms ~ 2 seconds later: (Note that the hiatus between successive logged events can be very informative!)

2568: {"type":"LOG_DATA","tutor":"story.echo::vow.A..Z.asc.lc.6__it_4","class":"INFO","tag":"TSTag","time":"1666600126266","data":{"BACKBUTTON":"PRESSED"}},

So perhaps nothing was displayed to read aloud, just a gray screen?

2569: {"type":"LOG_DATA","tutor":"story.echo::vow.A..Z.asc.lc.6__it_4","class":"INFO","tag":"MENU_BUG","time":"1666600126269","data":{"compare lastTutorPlayed=story.echo":""}},

I don't know what MENU_BUG signifies, but it doesn't sound good.

It looks like the kid picked "do it again":

2604: {"type":"LOG_DATA","tutor":"story.echo::vow.A..Z.asc.lc.6__it_4","class":"TUTORSTATE","tag":"TSTag","time":"1666600135021","data":{"target":"activity_selector","type":"behavior","value":"BUTTON_BEHAVIOR",".intentDatanative":"",".dataSource[sharedliteracy]vow.A..Z.asc.lc.6":"",".promptAudiolets do it again":"",".intentstory.echo":"",".tutorIdstory.echo::vow.A..Z.asc.lc.6__it_4":"",".helpAudiolets do it again":"",".buttonidSbuttonRepeat":"",".buttonBehaviorSELECT_REPEAT":""}},

The same parse error recurred: 2605: {"type":"LOG_DATA","tutor":"story.echo::vow.A..Z.asc.lc.6__it_4","class":"INFO","tag":"RTag","time":"1666600135080","data":{"target":"ctutorgraph","action":"preenterscene","setdatasource":"[sharedliteracy]vow.A..Z.asc.lc.6"}},

2606: {"class":"ERROR","tag":"CRt_Component","type":"Exception","time":"1666600135913","msg":"Story Parse Error: ","exception":"org.json.JSONException: End of input at character 0 of "},

Some of the same errors recur, but I don't know if any of them matters:

2647: {"class":"ERROR","tag":"CTutor","type":"Exception","time":"1666600143943","msg":"Run Error:","exception":"java.lang.NullPointerException: Attempt to invoke virtual method 'java.lang.String java.lang.String.replaceAll(java.lang.String, java.lang.String)' on a null object reference"},

... RoboTutor moves on to math: 2668: {"type":"LOG_DATA","tutor":"activity_selector","class":"INFO","tag":"MENU_BUG","time":"1666600152129","data":{"CycleMatrixActivityMenu":" activeSkill=SELECT_MATH -- activeTutorId=bpop.mn"}},

2669: {"type":"LOG_DATA","tutor":"bpop.mn:0..9.MN-SD-UP-OFF1-BL1.incr.4","class":"INFO","tag":"RTag","time":"1666600152301","data":{"target":"ctutor","action":"create","tutorname":"bubble_pop"}},

... 2673: {"class":"ERROR","tag":"CTutor","type":"Exception","time":"1666600153006","msg":"ERROR: Duplicate child view in:Scontainer - Duplicate of: null","exception":"java.lang.Exception: no-exception"},

RTBagamoyo commented 2 years ago

story.parrot:.ltr-E.rand.20_i~_1.vffffft2fffra3641

RTBagamoyo commented 2 years ago

story.partot:.ltr-I.rand.24._it_1.vftfff SWtCD2fftf

RTBagamoyo commented 2 years ago

story.parrot::vow.A..Z.asc.lc.5__it_3.vftfffSWtCD2fftf

RTBagamoyo commented 2 years ago

story.parrot::1..4.SD_OFF1_INC.5__it_1.vftfffswtcd2fffra3641

RTBagamoyo commented 2 years ago

story.parrot::0..10.SD_OFF1_INC.7__it_1.vftfffSWtCD2fftf

RTBagamoyo commented 2 years ago

story.parrot::0..10.SS_OFF1_INC.3.vftfffSWtCD2fftf

RTBagamoyo commented 2 years ago

story.parrot::0..10.SD_OFF1_DES.8__it_1.vfftffft2fffra3641

RTBagamoyo commented 2 years ago

story.parrot::0..10.SS_OFF1_DES.4.vftfffswtcd2fffra3641

RTBagamoyo commented 2 years ago

story.reveal::0..10.SD_OFF1_DES.35.vfftffft2ffftra3641

RTBagamoyo commented 2 years ago

story.reveal::1..4.SD_OFF1_DES.33.vfftffft2fffra3641

RTBagamoyo commented 2 years ago

story.reveal::1..4.SS_OFF1_DES.29.vftfffswtcd2fftf

RTBagamoyo commented 2 years ago

story.reveal::1..4.SS_OFF1_INC.28.vftfffswtcd2fffra3641

RTBagamoyo commented 2 years ago

story.hear:School_Welcome_Song._it_1.vfftffft2fffra3641

RTBagamoyo commented 2 years ago

story.hear::Kusoma_Welcome_Song__it_1.vftfffswtcd2fffra3641

RTBagamoyo commented 2 years ago

story.hear::UC_Vowel_Song_1__it_5.vftfffSWtCD2fftf

RTBagamoyo commented 2 years ago

story.hear::UC_Vowel_Song_1it1.vfftffft2fffra3641

JackMostow commented 1 year ago

Note that all reported gray screen errors are story.echo, story.parrot, story.reveal (all of which use ASR), or story.hear (which doesn't).

"Story Parse Error" occurs only twice:

comp_reading/src/main/java/cmu/xprize/rt_component/CRt_Component.java line 590

comp_questions/src/main/java/cmu/xprize/comp_questions/CQn_Component.java line 721

story.echo is not a comprehension activity, so the bug must have occurred in CRt_Component.java, not CQn_Component.java.

Let's see if we can replicate the bug by picking one of the activities that started with a gray screen. story.parrot::1..4.SD_OFF1_INC.5it did not. Let's see if config.json matches: story.parrot::1..4.SD_OFF1_INC.5it_1.vftfffswtcd2fffra3641 -- yes except for developer menu.

So bug does not appear deterministic (:<), unless the developer menu prevents it from occurring.

JackMostow commented 1 year ago

Logging stack trace for errors (#125) should (we hope) shed light on expected future instances of gray screen bug.

RTBagamoyo commented 1 year ago

Tablet number: 6111000852 RT version: 3.2.2.1 Date: 2023/02/06 Time: 11:07

Grey screen appeared on exercise, story.reveal::1..4SD_OFF1_INC.32.vftfffSWtCD2fftf

image

RTBagamoyo commented 1 year ago

Tablet number: 6111000885 RT version: 3.5.0.1 Date: 2023/03/07 Time: 08.31 image

RTBagamoyo commented 1 year ago

Tablet number: 6111000983 RT version: 3.2.2.1 Date: 2023/03/13 Time: 09.19

image

JackMostow commented 1 year ago

Look for gray_screen_bug in source code -- could it shed light on this bug?