Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Bug report: 3.5.0.1 gray screen #120

Open
JackMostow opened this issue Oct 27, 2022 · 25 comments
Open

Bug report: 3.5.0.1 gray screen #120

JackMostow opened this issue Oct 27, 2022 · 25 comments
Assignees
@JackMostow @pravallika10473 @bhargavmyadam @Bhu11154
Labels
bug Something isn't working

Comments

@JackMostow
Copy link
Contributor

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.
@JackMostow JackMostow added the bug Something isn't working label Oct 27, 2022
@RTBagamoyo
Copy link
Collaborator

They look like this:

image

@RTBagamoyo
Copy link
Collaborator

RTBagamoyo commented Oct 31, 2022 •
edited by JackMostow
Loading

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

  • Tablet: 6111000161
    Version: 3.5.0.1
    Date: 2022/10/19
    Time: 11:13

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
Copy link
Collaborator

RTBagamoyo commented Oct 31, 2022 •
edited by JackMostow
Loading

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

  • Tablet: 6109000572
    Version: 3.5.0.1
    Date: 2022/10/24
    Time: 11:28

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
Copy link
Collaborator

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

  • Tablet: 6111000885
    Version: 3.5.0.1
    Date: 2022/10/25
    Time: 11:00

@RTBagamoyo
Copy link
Collaborator

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

  • Tablet: 6111001724
    Version: 3.2.2.1
    Date: 2022/10/24
    Time: 12:15

@RTBagamoyo
Copy link
Collaborator

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

  • Tablet: 6111002134
    Version: 3.2.2.1
    Date: 2022/10/24
    Time: 11:29

@RTBagamoyo
Copy link
Collaborator

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

  • tablet: 6111000885
    Version: 3.5.0.1
    Date: 2022/10/20
    Time: 11:24

@RTBagamoyo
Copy link
Collaborator

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

  • tablet: 6111002134
    Version: 3.2.2.1
    Date: 2022/10/19
    Time: 11:17

@RTBagamoyo
Copy link
Collaborator

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

  • Tablet: 6111000983
    Version: 3.2.2.1
    Date: 2022/10/24
    Time: 12:23

@RTBagamoyo
Copy link
Collaborator

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

  • tablet: 6111000955
    Version: 3.5.0.1
    Date: 2022/10/25
    Time: 11:18

@RTBagamoyo
Copy link
Collaborator

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

  • tablet: 6111000955
    Version: 3.5.0.1
    Date: 2022/10/20
    Time: 11:23

@RTBagamoyo
Copy link
Collaborator

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

  • Tablet: 6111000885
    Version: 3.5.0.1
    Date: 2022/10/25
    Time: 11:12

@RTBagamoyo
Copy link
Collaborator

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

  • Tablet: 6111000885
    Version: 3.5.0.1
    Date: 2022/10/25
    Time: 10:59

@RTBagamoyo
Copy link
Collaborator

RTBagamoyo commented Oct 31, 2022 •
edited
Loading

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

  • tablet: 6111000885
    Version: 3.5.0.1
    Date: 2022/10/20
    Time: 11:17

  • tablet: 6111000955
    Version: 3.5.0.1
    Date: 2022/10/20
    Time: 11:19

  • Tablet: 6111001724
    Version: 3.2.2.1
    Date: 2022/10/24
    Time: 12:15

@RTBagamoyo
Copy link
Collaborator

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

  • Tablet: 6111000885
    Version: 3.5.0.1
    Date: 2022/10/20
    Time: 11:15

@RTBagamoyo
Copy link
Collaborator

story.hear:School_Welcome_Song._it_1.vfftffft2fffra3641

  • Tablet: 6111000955
    Version: 3.5.0.1
    Date: 2022/10/25
    Time: 11:25

@RTBagamoyo
Copy link
Collaborator

story.hear::Kusoma_Welcome_Song__it_1.vftfffswtcd2fffra3641

  • tablet: 6111000955
    Version: 3.5.0.1
    Date: 2022/10/20
    Time: 11:00

@RTBagamoyo
Copy link
Collaborator

story.hear::UC_Vowel_Song_1__it_5.vftfffSWtCD2fftf

  • Tablet: 6111000852
    Version: 3.2.2.1
    Date: 2022/10/24
    Time: 11:29

@RTBagamoyo
Copy link
Collaborator

story.hear::UC_Vowel_Song_1__it__1.vfftffft2fffra3641

  • tablet: 6111000955
    Version: 3.5.0.1
    Date: 2022/10/20
    Time: 11:00

@RoboTutorLLC RoboTutorLLC deleted a comment from pravallika10473 Dec 6, 2022
@JackMostow
Copy link
Contributor Author

JackMostow commented Dec 14, 2022 •
edited
Loading

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.5__it did not.
Let's see if config.json matches:
story.parrot::1..4.SD_OFF1_INC.5__it_1.vftfffswtcd2fffra3641
-- yes except for developer menu.

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

@JackMostow
Copy link
Contributor Author

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

@RTBagamoyo
Copy link
Collaborator

RTBagamoyo commented Feb 27, 2023 •
edited
Loading

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
Copy link
Collaborator

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

@RTBagamoyo
Copy link
Collaborator

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

image

@JackMostow
Copy link
Contributor Author

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@JackMostow JackMostow

@pravallika10473 pravallika10473

@bhargavmyadam bhargavmyadam

@Bhu11154 Bhu11154

Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@JackMostow @pravallika10473 @bhargavmyadam @Bhu11154 @RTBagamoyo