raspberrypi / scratch

Scratch releases
79 stars 21 forks source link

next-error message #188

Closed heppg closed 8 years ago

heppg commented 8 years ago

Some kids in class encounter this problem: an error popup is shown. Reason unknown. problem_next One of the problems could be that the kids work for almost half a year with their code and a lot of load and save operations have been executed.

tobiasbp commented 8 years ago

When does the error occur? On saving the document? What version are you using?

On Mon, 11 Apr 2016 at 14:07 heppg notifications@github.com wrote:

Some kids in class encounter this problem: an error popup is shown. Reason unknown. [image: problem_next] https://cloud.githubusercontent.com/assets/5240331/14426269/2d2eb5fa-ffee-11e5-895d-733b8ab388dc.jpg One of the problems could be that the kids work for almost half a year with their code and a lot of load and save operations have been executed.

— You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub https://github.com/raspberrypi/scratch/issues/188

timrowledge commented 8 years ago

There are two things that can help me a lot if this ever happens a) press that 'Debug' button! Unless something is truly terribly broken it will open a debugger (surprise!) and the top pane will list how it got into trouble. Curious kids (or adults) might even notice some of the details the resulting code shows. They might even get hooked on Smalltalk. b) there should be a file aimed SqueakDebug.log (or something like that) in the home directory. Right now that ends up being the /root directory because of the annoying ( and soon to be fixed) requirement to run under sudo. Send me that file if at all possible.

The next release will have a fix to the problem that the error window is showing here, where it doesn't show the last few message sends, which would immediately give me better ideas as to what went wrong. My only decent guess from what we have here is that it was trying to save a file and something prevented the file opening (thus the sending of #next: to nil) and that might be because of the SD card running out of room?

heppg commented 8 years ago

Here some first results from my last visit in school: SqueakDebug.log.txt

Version of scratch is "2015-09-15". Quite old, but we have extraordinary conditions that this course runs longer than half a year now.

Pressing 'debug' is done, but screenshots are still on machine (copy paste is (sometimes) a miracle). Takes some days till next lessons to get them.

Project is quite large, but works on my machine. So no more results from this.

timrowledge commented 8 years ago

The debug log in clear - MessageNotUnderstood: UndefinedObject>>next: 6 November 2015 10:31:54.357 am

VM: unix - Smalltalk Image: Squeak5.0 [latest update: #15113]

SecurityManager state: Restricted: false FileAccess: true SocketAccess: true Working Dir /usr/share/scratch Trusted Dir /usr/share/scratch/secure Untrusted Dir /home/pi/Scratch

UndefinedObject(Object)>>doesNotUnderstand: #next: Receiver: nil Arguments and temporary variables: t1: next: 10000 t2: MessageNotUnderstood: UndefinedObject>>next: t3: nil Receiver's instance variables: nil MessageSocket>>sendStreamData Receiver: a MessageSocket Arguments and temporary variables: t1: nil t2: nil Receiver's instance variables: socket: a Socket[connected] inSizeBuf: #[0 0 0 0] inSizeIndex: 1 inBuf: nil inIndex: 1 outgoingMessages: an OrderedCollection('sensor-update "Name" "njhmnjmgbbbmbbmgk...etc... outBuf: nil outIndex: 1 lastActivityTime: 3624258568

MessageSocket>>sendData Receiver: a MessageSocket Arguments and temporary variables: t1: nil t2: nil t3: nil Receiver's instance variables: socket: a Socket[connected] inSizeBuf: #[0 0 0 0] inSizeIndex: 1 inBuf: nil inIndex: 1 outgoingMessages: an OrderedCollection('sensor-update "Name" "njhmnjmgbbbmbbmgk...etc... outBuf: nil outIndex: 1 lastActivityTime: 3624258568

[] in ScratchServer>>sendOutgoingCommands Receiver: a ScratchServer Arguments and temporary variables: t1: a MessageSocket t2: 'sensor-update "Name" "njhmnjmgbbbmbbmgkµħđŧj,gdhgdhbtd mzfrg,njzfrnj,uzrf"...etc... Receiver's instance variables: stage: a ScratchStageMorph(3942326) userName: 'Scratch' serverSocket: a Socket[waitingForConnection] incomingUDPSocket: a Socket[connected] peerSockets: an OrderedCollection(a MessageSocket) peerNames: an IdentityDictionary() sensors: a Dictionary() lastSentValues: a Dictionary() incomingBroadcasts: an OrderedCollection() outgoingBroadcasts: an OrderedCollection() in: nil broadcastCache: a Set()

OrderedCollection>>do: Receiver: an OrderedCollection(a MessageSocket) Arguments and temporary variables: t1: [closure] in ScratchServer>>sendOutgoingCommands t2: 1 Receiver's instance variables: array: {a MessageSocket . nil . nil . nil . nil . nil . nil . nil . nil . nil} firstIndex: 1 lastIndex: 1

ScratchServer>>sendOutgoingCommands Receiver: a ScratchServer Arguments and temporary variables: t1: 'sensor-update "Name" "njhmnjmgbbbmbbmgkµħđŧj,gdhgdhbtd mzfrg,njzfrnj,uzrf"...etc... Receiver's instance variables: stage: a ScratchStageMorph(3942326) userName: 'Scratch' serverSocket: a Socket[waitingForConnection] incomingUDPSocket: a Socket[connected] peerSockets: an OrderedCollection(a MessageSocket) peerNames: an IdentityDictionary() sensors: a Dictionary() lastSentValues: a Dictionary() incomingBroadcasts: an OrderedCollection() outgoingBroadcasts: an OrderedCollection() in: nil broadcastCache: a Set()

ScratchServer>>stepServer Receiver: a ScratchServer Arguments and temporary variables:

Receiver's instance variables: 
    stage:  a ScratchStageMorph(3942326)
    userName:   'Scratch'
    serverSocket:   a Socket[waitingForConnection]
    incomingUDPSocket:  a Socket[connected]
    peerSockets:    an OrderedCollection(a MessageSocket)
    peerNames:  an IdentityDictionary()
    sensors:    a Dictionary()
    lastSentValues:     a Dictionary()
    incomingBroadcasts:     an OrderedCollection()
    outgoingBroadcasts:     an OrderedCollection()
    in:     nil
    broadcastCache:     a Set()

ScratchStageMorph>>stepServers Receiver: a ScratchStageMorph(3942326) Arguments and temporary variables:

Receiver's instance variables: 
    bounds:     546@71 corner: 1026@431
    owner:  a ScratchFrameMorph(4189604)
    submorphs:  {a ScratchSpriteMorph(3684534) . a ScratchSpriteMorph(3981900) . a S...etc...
    fullBounds:     nil
    color:  Color white
    extension:  a MorphExtension (3513451) [other:  (dropEnabled -> true) (dragEnabl...etc...
    objName:    'Bühne'
    vars:   a Dictionary('Name'->'njhmnjmgbbbmbbmgkµħđŧj,gdhgdhbtd mzfrg,njzfrnj,uzrf...etc...
    lists:  a Dictionary('cp x'->a ScratchListMorph(3170799) 'cp y'->a ScratchListMo...etc...
    blocksBin:  a ScratchScriptsMorph(3000128)
    isClone:    false
    media:  an OrderedCollection(map1 [image] Plopp [sound] Hintergrund2 [image] Hin...etc...
    costume:    Hintergrund15 [image]
    costumeChangeMSecs:     213928
    filterPack:     nil
    visibility:     100
    volume:     100
    tempoBPM:   60
    sceneStates:    a Dictionary()
    zoom:   1.0
    hPan:   0
    vPan:   0
    penTrailsForm:  nil
    lastPenPositions:   nil
    runningBlocks:  an OrderedCollection(an EventHatMorph(2522835) an EventHatMorph(...etc...
    inProcessStep:  false
    sensorBoard:    a SensorBoardMorph(3434466)
    midiPortNum:    -1
    midiPort:   nil
    notePlayerDict:     a Dictionary(a ScratchSpriteMorph(1189362)->a ScratchNotePlayer...etc...
    obsoleteSavedState:     nil
    sprites:    an OrderedCollection(a ScratchSpriteMorph(2323111) a ScratchSpriteMorp...etc...
    scratchServer:  a ScratchServer
    isQuarterSize:  false
    cachedForm:     nil
    showMotorBlocks:    false
    cachedBackground:   Form(480x360x32)
    gpioServer:     nil

ScratchFrameMorph>>step Receiver: a ScratchFrameMorph(4189604) Arguments and temporary variables: t1: 1036@772 t2: nil Receiver's instance variables: bounds: 0@0 corner: 1036@772 owner: a PasteUpMorph(2434915) [world] submorphs: {an ImageFrameMorph(2808071) . a ScratchStageMorph(3942326) . a Scra...etc... fullBounds: 0@0 corner: 1036@815 color: Color blue extension: a MorphExtension (2961978) [sticky] topPane: an ImageFrameMorph(3265517) viewerPane: a ScratchViewerMorph(1572921) scriptsPane: a ScratchScriptEditorMorph(1844776) stageFrame: an ImageFrameMorph(3975981) workPane: a ScratchStageMorph(3942326) titlePane: an ImageFrameMorph(2472820) libraryPane: a ScratchLibraryMorph(3432041) menuPanel: a DockingBarMorph(631976) stageButtonsPanel: an AlignmentMorph(592057) readoutPane: an ImageFrameMorph(2808071) logoMorph: a SketchMorph(1088984) projectTitleMorph: a StringMorph(3975928)'box14_20160201_2' flagButton: a ToggleButton(3978527) fillScreenFlag: true paintingInProgress: false projectDirectory: UnixFileDirectory on '/home/pi/Scratch' projectName: 'box14_20160201_2.sb' projectInfo: a Dictionary('author'->'' 'history'->'2015-11-5 05:21:45.39 save u...etc... author: '' loginName: '' loginPassword: '' watcherPositions: a Dictionary() shuffledCostumeNames: nil justSaved: false viewModeButtons: an OrderedCollection(a ToggleButton(1520475) a ToggleButton(29...etc... viewMode: #normal lastViewMode: nil viewModeButtonsPanel: an AlignmentMorph(3802766) toolbarPanel: an AlignmentMorph(876971) lastWeDoPoll: 66923

ScratchFrameMorph(Morph)>>stepAt: Receiver: a ScratchFrameMorph(4189604) Arguments and temporary variables: t1: 214487 t2: nil Receiver's instance variables: bounds: 0@0 corner: 1036@772 owner: a PasteUpMorph(2434915) [world] submorphs: {an ImageFrameMorph(2808071) . a ScratchStageMorph(3942326) . a Scra...etc... fullBounds: 0@0 corner: 1036@815 color: Color blue extension: a MorphExtension (2961978) [sticky] topPane: an ImageFrameMorph(3265517) viewerPane: a ScratchViewerMorph(1572921) scriptsPane: a ScratchScriptEditorMorph(1844776) stageFrame: an ImageFrameMorph(3975981) workPane: a ScratchStageMorph(3942326) titlePane: an ImageFrameMorph(2472820) libraryPane: a ScratchLibraryMorph(3432041) menuPanel: a DockingBarMorph(631976) stageButtonsPanel: an AlignmentMorph(592057) readoutPane: an ImageFrameMorph(2808071) logoMorph: a SketchMorph(1088984) projectTitleMorph: a StringMorph(3975928)'box14_20160201_2' flagButton: a ToggleButton(3978527) fillScreenFlag: true paintingInProgress: false projectDirectory: UnixFileDirectory on '/home/pi/Scratch' projectName: 'box14_20160201_2.sb' projectInfo: a Dictionary('author'->'' 'history'->'2015-11-5 05:21:45.39 save u...etc... author: '' loginName: '' loginPassword: '' watcherPositions: a Dictionary() shuffledCostumeNames: nil justSaved: false viewModeButtons: an OrderedCollection(a ToggleButton(1520475) a ToggleButton(29...etc... viewMode: #normal lastViewMode: nil viewModeButtonsPanel: an AlignmentMorph(3802766) toolbarPanel: an AlignmentMorph(876971) lastWeDoPoll: 66923

StepMessage(MorphicAlarm)>>value: Receiver: StepMessage(#stepAt: -> a ScratchFrameMorph(4189604))(a ScratchFrameMorph(4189604) #stepAt...etc... Arguments and temporary variables: t1: 214487 t2: 0 Receiver's instance variables: receiver: a ScratchFrameMorph(4189604) selector: #stepAt: arguments: nil scheduledTime: 213997 sequenceNumber: nil numArgs: 1 stepTime: nil

WorldState>>runLocalStepMethodsIn: Receiver: a WorldState Arguments and temporary variables: t1: a PasteUpMorph(2434915) [world] t2: 214487 t3: a ScratchFrameMorph(4189604) t4: 600 t5: a PasteUpMorph(2434915) [world] Receiver's instance variables: hands: {a HandMorph(2917085)} activeHand: a HandMorph(2917085) viewBox: 0@0 corner: 1036@772 canvas: a FormCanvas on: DisplayScreen(1036x772x32) damageRecorder: a DamageRecorder stepList: a Heap(StepMessage(#stepAt: -> a Morph(2827086))(a Morph(2827086) #st...etc... lastStepTime: 213750 lastStepMessage: StepMessage(#stepAt: -> a ScratchFrameMorph(4189604))(a Scratc...etc... lastCycleTime: 213770 commandHistory: a CommandHistory alarms: a MorphicAlarmQueue() lastAlarmTime: 214487 remoteServer: nil multiCanvas: nil interCycleDelay: a Delay(20 msecs)

WorldState>>runStepMethodsIn: Receiver: a WorldState Arguments and temporary variables: t1: a PasteUpMorph(2434915) [world] t2: a SharedQueue(0) t3: nil t4: 200 t5: 214487 Receiver's instance variables: hands: {a HandMorph(2917085)} activeHand: a HandMorph(2917085) viewBox: 0@0 corner: 1036@772 canvas: a FormCanvas on: DisplayScreen(1036x772x32) damageRecorder: a DamageRecorder stepList: a Heap(StepMessage(#stepAt: -> a Morph(2827086))(a Morph(2827086) #st...etc... lastStepTime: 213750 lastStepMessage: StepMessage(#stepAt: -> a ScratchFrameMorph(4189604))(a Scratc...etc... lastCycleTime: 213770 commandHistory: a CommandHistory alarms: a MorphicAlarmQueue() lastAlarmTime: 214487 remoteServer: nil multiCanvas: nil interCycleDelay: a Delay(20 msecs)

PasteUpMorph>>runStepMethods Receiver: a PasteUpMorph(2434915) [world] Arguments and temporary variables:

Receiver's instance variables: 
    bounds:     0@0 corner: 1036@772
    owner:  nil
    submorphs:  {a ScratchFrameMorph(4189604)}
    fullBounds:     0@0 corner: 1036@772
    color:  (Color r: 0.909 g: 0.94 b: 0.976)
    extension:  a MorphExtension (1486755) [eventHandler = an EventHandler]  [other:...etc...
    borderWidth:    0
    borderColor:    (Color r: 0.091 g: 0.06 b: 0.024)
    presenter:  an EtoysPresenter (3576735)
    model:  a MorphicModel(1077632)
    cursor:     1
    padding:    3
    backgroundMorph:    nil
    turtleTrailsForm:   nil
    turtlePen:  nil
    lastTurtlePositions:    nil
    isPartsBin:     nil
    indicateCursor:     nil
    wantsMouseOverHalos:    nil
    worldState:     a WorldState
    griddingOn:     nil

WorldState>>doOneCycleNowFor: Receiver: a WorldState Arguments and temporary variables: t1: a PasteUpMorph(2434915) [world] t2: #(false) Receiver's instance variables: hands: {a HandMorph(2917085)} activeHand: a HandMorph(2917085) viewBox: 0@0 corner: 1036@772 canvas: a FormCanvas on: DisplayScreen(1036x772x32) damageRecorder: a DamageRecorder stepList: a Heap(StepMessage(#stepAt: -> a Morph(2827086))(a Morph(2827086) #st...etc... lastStepTime: 213750 lastStepMessage: StepMessage(#stepAt: -> a ScratchFrameMorph(4189604))(a Scratc...etc... lastCycleTime: 213770 commandHistory: a CommandHistory alarms: a MorphicAlarmQueue() lastAlarmTime: 214487 remoteServer: nil multiCanvas: nil interCycleDelay: a Delay(20 msecs)

WorldState>>doOneCycleFor: Receiver: a WorldState Arguments and temporary variables: t1: a PasteUpMorph(2434915) [world] Receiver's instance variables: hands: {a HandMorph(2917085)} activeHand: a HandMorph(2917085) viewBox: 0@0 corner: 1036@772 canvas: a FormCanvas on: DisplayScreen(1036x772x32) damageRecorder: a DamageRecorder stepList: a Heap(StepMessage(#stepAt: -> a Morph(2827086))(a Morph(2827086) #st...etc... lastStepTime: 213750 lastStepMessage: StepMessage(#stepAt: -> a ScratchFrameMorph(4189604))(a Scratc...etc... lastCycleTime: 213770 commandHistory: a CommandHistory alarms: a MorphicAlarmQueue() lastAlarmTime: 214487 remoteServer: nil multiCanvas: nil interCycleDelay: a Delay(20 msecs)

PasteUpMorph>>doOneCycle Receiver: a PasteUpMorph(2434915) [world] Arguments and temporary variables:

Receiver's instance variables: 
    bounds:     0@0 corner: 1036@772
    owner:  nil
    submorphs:  {a ScratchFrameMorph(4189604)}
    fullBounds:     0@0 corner: 1036@772
    color:  (Color r: 0.909 g: 0.94 b: 0.976)
    extension:  a MorphExtension (1486755) [eventHandler = an EventHandler]  [other:...etc...
    borderWidth:    0
    borderColor:    (Color r: 0.091 g: 0.06 b: 0.024)
    presenter:  an EtoysPresenter (3576735)
    model:  a MorphicModel(1077632)
    cursor:     1
    padding:    3
    backgroundMorph:    nil
    turtleTrailsForm:   nil
    turtlePen:  nil
    lastTurtlePositions:    nil
    isPartsBin:     nil
    indicateCursor:     nil
    wantsMouseOverHalos:    nil
    worldState:     a WorldState
    griddingOn:     nil

[] in MorphicProject>>spawnNewProcess Receiver: a MorphicProject (Unnamed1) in a PasteUpMorph(2434915) [world] Arguments and temporary variables:

Receiver's instance variables: 
    dependents:     nil
    world:  a PasteUpMorph(2434915) [world]
    uiManager:  a MorphicUIManager
    changeSet:  a ChangeSet named Unnamed1
    transcript:     a TranscriptStream
    parentProject:  a MorphicProject (Unnamed1) in a PasteUpMorph(2434915) [world]
    previousProject:    nil
    displayDepth:   32
    viewSize:   151@132
    thumbnail:  Form(151x132x32)
    nextProject:    nil
    guards:     nil
    projectParameters:  an IdentityDictionary(#PrevailingProjectFlags->an IdentityDi...etc...
    version:    nil
    urlList:    nil
    environment:    nil
    lastDirectory:  nil
    lastSavedAtSeconds:     nil
    projectPreferenceFlagDictionary:    an IdentityDictionary(#showSharedFlaps->true #...etc...
    resourceManager:    a ResourceManager
    uiProcess:  a Process in [] in BlockClosure>>newProcess

[] in BlockClosure>>newProcess Receiver: [closure] in MorphicProject>>spawnNewProcess Arguments and temporary variables:

Receiver's instance variables: 
    outerContext:   MorphicProject>>spawnNewProcess
    startpc:    53
    numArgs:    0

--- The full stack --- UndefinedObject(Object)>>doesNotUnderstand: #next: MessageSocket>>sendStreamData MessageSocket>>sendData [] in ScratchServer>>sendOutgoingCommands OrderedCollection>>do: ScratchServer>>sendOutgoingCommands ScratchServer>>stepServer ScratchStageMorph>>stepServers ScratchFrameMorph>>step ScratchFrameMorph(Morph)>>stepAt: StepMessage(MorphicAlarm)>>value: WorldState>>runLocalStepMethodsIn: WorldState>>runStepMethodsIn: PasteUpMorph>>runStepMethods WorldState>>doOneCycleNowFor: WorldState>>doOneCycleFor: PasteUpMorph>>doOneCycle [] in MorphicProject>>spawnNewProcess [] in BlockClosure>>newProcess

timrowledge commented 8 years ago

OK, this is a bit tricky to work out. So far as I can see this is ancient MIT code having trouble (in fact stuff dated 2003!) and may be being triggered by the 'Name'->'njhmnjmgbbbmbbmgkµħđŧj,gdhgdhbtd mzf... part; that is presumably a unicode string because of the 'kµħđŧj,' characters. That in turn is what gets us from MessageSocket>>sendData to the MessageSocket>>sendStreamData method.

What I see here is some messing with the buffering of socket data and evidently at some point all the data went out ok and we get to a curious bit of code that sets 'outbuf' to nil, and which would seem a reasonable cause for it being nil the next time around and thus causing the error.

The code looks like - MessageSocket>>#sendData sendData "Send some more data, if possible. Answer true if there is more data to be sent. This method should be called frequently by the client. It does nothing if there are no messages to send, or if the socket is not connected or ready to accept data. If outBuf is not a bytes object (i.e., a ByteArray or String) then assume it is a positionable stream and let sendStreamData send it."

| buf n msg |
(socket notNil and: [socket isConnected]) ifFalse: [^ false].
socket waitForSendDoneFor: self standardTimeout.

outBuf ifNil: [  "not currently sending"
    outgoingMessages size = 0 ifTrue: [^ false].  "no more message to send"
    socket sendDone ifFalse: [^ true].  "still sending last data"
    outgoingMessages first class isBytes ifFalse: [^ self sendStreamData].
    buf := WriteStream on: (ByteArray new: 2000).
    [outgoingMessages size > 0] whileTrue: [
        msg := outgoingMessages removeFirst squeakToUtf8 asByteArray "it really ought to be practical to convert directly to a byte array".
        buf uint32: msg size.
        buf nextPutAll: msg ].
    *outBuf := buf contents.*
    outIndex := 1].

outBuf ifNotNil: [  "currently sending outBuf"
    outBuf class isBytes ifFalse: [^ self sendStreamData].
    n := socket sendDataNoWait: outBuf startIndex: outIndex.
    n > 0 ifTrue: [
        lastActivityTime := Time totalSeconds.
        outIndex := outIndex + n.
        outIndex > outBuf size ifTrue: [outBuf := nil]]].

^ true

The bolded line outBuf := buf contents. is the only place where 'outbuf' is set to anything non-nil, and it is always set to the contents of a stream made from the outgoing message text (which may be simple ascii bytes or a 32bit wide unicode string converted to utf8 encoding as appears to be the case here) with a small header to specify how long it is. However, if the 'outgoingMessages first' - i.e. the first item in the list of outgoing stuff - is not a byte string (which it isn't, here) then we can get to - MessageSocket>>#sendStreamData sendStreamData "Private! Used by sendData only when outBuf is a positionable stream. Send some data from outBuf, if possible. Set outBuf to nil when the entire stream has been sent. Always answer true. "

| tempBuf n |
tempBuf := outBuf next: 10000.  "read up to 10000 bytes from the stream"
outBuf skip: tempBuf size negated.
n := socket sendDataNoWait: tempBuf startIndex: 1.
n > 0 ifTrue: [
    lastActivityTime := Time totalSeconds.
    outBuf skip: n.
    outBuf atEnd ifTrue: [outBuf := nil]]. "finished sending outbuf"

^ true

Tracing this all back a bit we see that the only input point is within ScratchServer>>#sendOutgoingCommands, which derives the data to be sent from ScratchServer>>variableUpdateMessage. Old Scratch kept any non-Latin1 related strings as a weird class 'UTF8' which got converted in odd places and somewhat confusing times; NuScratch leaves strings in either byte or wide form as much as possible; I evidently missed a place where a wide string might need converting to utf8 encoding before sending via a socket. Since the old Scratch 'UTF*' class is a subclass of String and thus 'blahblah class isBytes' is true, we would never actually get to run #sendStreamData and thus never have this particular problem.

Sigh. Now to fix it.

timrowledge commented 8 years ago

The problem is that old Scratch assumed all strongish things were UTF8 class objects, which meant them being byte objects. So the line outgoingMessages first class isBytes ifFalse: [^ self sendStreamData]. can be changed to outgoingMessages first isString ifFalse: [^ self sendStreamData]. to handle both wide and byte Strings. This should solve our problem cleanly with minimal changes. It is probably the case that the entire thing could be cleaned up more since it seems nothing can actually add non-String data to the outgoingMessages list and so the sendStreamData method is almost certainly redundant.

Fix prepped for next release.

GHP, as a test, you might like to make that change in your working image.

timrowledge commented 8 years ago

This went out in Scratch-tpr.334 and the following release