Data loss (incomplete .log files) & crash at script's end [MWE debug script available]

Builder
1

An older problem I’ve been having with PsychoPy, in which the script crashes at the very end, with incomplete .log files being produced, is rearing its ugly head again.

This is not an easy problem to reproduce without having a look at the script in question, which I’ve simplified into a minimum working example (MWE) and uploaded here. Nonetheless I would really appreciate it if someone were able to try to reproduce this, as it has led to a very disruptive data loss for an ongoing experiment.

Manifestation:
– script runs well till the end, but the very final screen of the experiment (thankYou message) becomes unresponsive and script crashes at that point upon any key being pressed
– the (painful) consequence of this is that the .LOG output file of the run, which contains crucial timing data, is only partially saved. Surprisingly, events stop being logged much earlier than the crash moment (end of the script). For instance here is the contents of a typical such .LOG file, where logging stops at the very first trial:

4.6283 EXP Created window1 = Window(allowGUI=True, allowStencil=False, autoLog=True, bitsMode=UNKNOWN, blendMode=‘avg’, color=array([ 0., 0., 0.]), colorSpace=‘rgb’, fullscr=UNKNOWN, gamma=None, lms=UNKNOWN, monitor=<psychopy.monitors.calibTools.Monitor object at 0x158C4C70>, name=‘window1’, pos=[0, 0], screen=0, size=array([1920, 1080]), stereo=False, units=u’norm’, useFBO=True, useRetina=False, viewOri=0.0, viewPos=None, viewScale=None, waitBlanking=True, winType=‘pyglet’)
4.6283 EXP window1: recordFrameIntervals = False
4.7930 EXP window1: recordFrameIntervals = True
4.9754 EXP window1: recordFrameIntervals = False
5.2385 EXP Created instructionsText = TextStim(alignHoriz=‘center’, alignVert=‘center’, antialias=True, autoLog=True, bold=False, color=‘white’, colorSpace=‘named’, contrast=1.0, depth=-1.0, flipHoriz=False, flipVert=False, font=‘Arial’, fontFiles=, height=0.06, italic=False, name=‘instructionsText’, opacity=1.0, ori=0, pos=array([ 0., 0.]), rgb=array([ 255., 255., 255.]), text=unicode(…), units=u’norm’, win=Window(…), wrapWidth=1)
5.2487 EXP Created text_scannerSync = TextStim(alignHoriz=‘center’, alignVert=‘center’, antialias=True, autoLog=True, bold=False, color=‘white’, colorSpace=‘named’, contrast=1.0, depth=0.0, flipHoriz=False, flipVert=False, font=‘Arial’, fontFiles=, height=0.06, italic=False, name=‘text_scannerSync’, opacity=1.0, ori=0, pos=array([ 0., 0.]), rgb=array([ 255., 255., 255.]), text=unicode(…), units=u’norm’, win=Window(…), wrapWidth=1)
5.2585 EXP Created text_scannerSync = TextStim(alignHoriz=‘center’, alignVert=‘center’, antialias=True, autoLog=True, bold=False, color=‘white’, colorSpace=‘named’, contrast=1.0, depth=0.0, flipHoriz=False, flipVert=False, font=‘Arial’, fontFiles=, height=0.06, italic=False, name=‘text_scannerSync’, opacity=1.0, ori=0, pos=array([ 0., 0.]), rgb=array([ 255., 255., 255.]), text=unicode(…), units=u’norm’, win=Window(…), wrapWidth=1)
5.2688 EXP Created text_scannerSync = TextStim(alignHoriz=‘center’, alignVert=‘center’, antialias=True, autoLog=True, bold=False, color=‘white’, colorSpace=‘named’, contrast=1.0, depth=0.0, flipHoriz=False, flipVert=False, font=‘Arial’, fontFiles=, height=0.06, italic=False, name=‘text_scannerSync’, opacity=1.0, ori=0, pos=array([ 0., 0.]), rgb=array([ 255., 255., 255.]), text=unicode(…), units=u’norm’, win=Window(…), wrapWidth=1)
5.2786 EXP Created text_scannerSync = TextStim(alignHoriz=‘center’, alignVert=‘center’, antialias=True, autoLog=True, bold=False, color=‘white’, colorSpace=‘named’, contrast=1.0, depth=0.0, flipHoriz=False, flipVert=False, font=‘Arial’, fontFiles=, height=0.06, italic=False, name=‘text_scannerSync’, opacity=1.0, ori=0, pos=array([ 0., 0.]), rgb=array([ 255., 255., 255.]), text=unicode(…), units=u’norm’, win=Window(…), wrapWidth=1)
5.2883 EXP Created text_scannerSync = TextStim(alignHoriz=‘center’, alignVert=‘center’, antialias=True, autoLog=True, bold=False, color=‘white’, colorSpace=‘named’, contrast=1.0, depth=0.0, flipHoriz=False, flipVert=False, font=‘Arial’, fontFiles=, height=0.06, italic=False, name=‘text_scannerSync’, opacity=1.0, ori=0, pos=array([ 0., 0.]), rgb=array([ 255., 255., 255.]), text=unicode(…), units=u’norm’, win=Window(…), wrapWidth=1)
5.2950 EXP Created cross_P = ImageStim(autoLog=True, color=array([ 1., 1., 1.]), colorSpace=‘rgb’, contrast=1.0, depth=-1.0, flipHoriz=False, flipVert=False, image=‘images/fixationCross_black.png’, interpolate=True, mask=None, maskParams=None, name=‘cross_P’, opacity=1.0, ori=0.0, pos=array([ 0., 0.]), size=array([ 0.18645833, 0.46296296]), texRes=128, units=u’norm’, win=Window(…))
5.2992 EXP Created speaker_P = ImageStim(autoLog=True, color=array([ 1., 1., 1.]), colorSpace=‘rgb’, contrast=1.0, depth=-2.0, flipHoriz=False, flipVert=False, image=‘images/speaker.png’, interpolate=True, mask=None, maskParams=None, name=‘speaker_P’, opacity=1.0, ori=0.0, pos=array([ 0., 0.]), size=array([ 0.20833333, 0.30740741]), texRes=128, units=u’norm’, win=Window(…))
6.3309 EXP Set sound=C

– the CSV&XLSX outputs containing subject responses are recorded fine, all the way till the end of the script, it’s just the .log that is incomplete

In an attempt to isolate the caus of this behaviour, I ran the script with various combinations of (fewer and fewer) blocks, by editing the blockSelection.xlsx conditions file. With this debug manipulation, I was able to run the script without the bug. My only conclusion is that the final-screen crash appears after a certain number of trials (or: blocks?) have been run, as if some internal (memory) stack fills up and makes psychopy unable to complete the execution of the script (and thus flush the .LOG) properly. The blockSelection.xlsx of the MWE example script uploaded is at the minimum “load” required for the bug to appear: it suffices for only the final row (block) to be deleted from blockSelection.xlsx for the bug to disappear and the script to run well (i.e. no crash & complete .LOG).

Adding “logging.flush()” to a code component in the trial routine, as I’ve been advised in the past, is no good: while the .log file is indeed written into at trial-level (and not at the end of the script), this workaround always leads to a crash of the script at the end of the trial containing this code, such that the final .LOG is still not complete.

As a side question, given that the .LOGs for all my data so far are incomplete, do I perhaps have a chance of recovering the event timing data from the .psydata output?

Very much appreciate any help with this.

OS (e.g. Win10): Win7
PsychoPy version (e.g. 1.84.x): 1.84.2

2

By adding logging.flush() to the EndRoutine tab of a code component in each trial, I can make the .log file be saved all the way through the experiment. However, the script still crashes at the final trial; strangely, it is data for the final block (with all of its trials) that is not recorded as a result of this, rather than just data from the final trial, even though the flush should happen at the end of each trial, not at the end of a block.

ANy thoughts at all?

EDIT: actually, the script freezes not just at the very end but also mi-dway. however always at the end of a routine (could be either one routine or another - seems random). I am completely at my wit’s end here.

3

Would have never thought what was causing this…

It was because I had set the duration of the static ISI component (on the top of my trial routine) to zero, since I am defining my ISI differently (having the first event in the trial start $my_ISI seconds into the trial). As soon as I’ve set that to a non-zero duration (or indeed deleted that component), the crash no longer occurred.

4

It would still be good to know whether the psydat file contains any timing information about the events in the experiment (the last question in my OP). If not, a whole collected data set will be rendered meaningless. The only consolation would be if this bug (that I luckily managed to discover by myself on this occasion), will be addressed in a future version.

5

Setting a Static Period to zero causes the experiment to hang at the end? I’m not sure why it would do that but I could look into it. I would delete the static period rather than setting it to have zero duration. I can imagine that asking the computer to be static for exactly zero seconds would lead to problems (but not this one, as I say). Not sure I’d call that a bug as such - sounds like “surprising” user behaviour.

psydat files do not save timing information unless you tell them to save timing information. I’m guessing you didn’t so, no, it isn’t there. Log files are designed to store a huge stream of mostly-meaningless information in case you make a mistake with the manual saving of data.

Sorry if that means a “whole collected data set will be meaningless”. Do you mean you collected all your data before opening the files to see if you were storing the data you needed?!! I can’t stress heavily enough the importance of checking your data and your experiment before collecting the main data. PsychoPy is written by volunteers for free and provided with no warranty. It’s up to you to make sure everything in your experiment is working as expected in your study.

2 Likes
6

Hi Jon

I agree that I should have deleted the static ISI instead of setting it to zero. Definitely surprising user behaviour there! Also, I fully understand that PsychoPy is provided with no “customer service”, so I was not expecting (although hoping) to necessarily receive help with this issue. It was definitely my mistake not to have also checked the contents of the LOG files to see that everything is indeed logged rather than them being trimmed half-way through; I was merely checking that all output files are there after each run, and not 0kB-sized. I did actually check the contents of some output files picked up random - but only picked CSVs and XLSXs, since they are more “earder-friendly”.

Oh well, good at least that other users will be able to learn from this mistake and know a solution, should they encounter a similar problem with the zero-duration component.

Thanks again for your input.

7

Unrelated to that, however, the two most recent versions do seem to crash this script even after the ISI=0 component has been removed. The same script runs just fine on 1.83.04. See separate thread where I report this.