BrainStreamLogFile
Log file
BrainStream creates a log file for each block of your experiment. The log file gives an overview of everything that happened during your experiment. You can find the log file in the [.DocsSectionsPathsFolders#OutputFolder runfolder] of your experiment.
As the log file contains a lot of information it is sometimes difficult to find the information you are looking for. In the following, we will show which information is included in the log file and where it can be found. We will use File:BrainStreamDocs Log-09Nov2011-10h47m38s.docx log file as an example. The log file belongs to the experiment described [.DocsSectionsExampleSentences here].
Date and time
Each new line of the log file begins with a date and time:
09Nov11|10:47:38.928 INFO >
Date and time are derived from the computer which executes the actions. Note that if you are using [.DocsSectionsParallelMode#SecClients parallel clients] on multiple computers, computer times of the different machines may not be synchronous. Although this may be confusing when reading the log file, it has no influence on the timing of executed actions.
The date and time can be followed either by INFO or WARN. This is related to the blocksetting [.DocsSectionsBlockFile#KeyVerbosityLevel VerbosityLevel]. If VerbosityLevel was set to INFO, all information in INFO and WARN lines of the log file have also been shown in the Matlab command window during the experiment. If VerbosityLevel was set to WARNING, only the WARN lines of the log file have been shown in the Matlab command window. Additionally, you can use the [.DocsSectionsProgrmmersGuide#bs_msg bs_msg] and [.DocsSectionsProgrmmersGuide#bs_warn bs_warn] functions to write messages to the log file yourself.
Experiment initialization
The first part of the log file describes everything that happened before the onset of BrainStream processing, that is, before the BS_INIT marker arrives. For example, you may find information about
- reading settings from the [.DocsSectionsBuildingExperiments#SecBlock block file]
09Nov11|10:47:46.593 INFO > Read from block settings: [[TriggerSource|Trigger Source]] = default 09Nov11|10:47:46.593 INFO > Default used for [[TriggerDef|Trigger Def]] (failed reading from block settings
- loading files or functions
09Nov11|10:47:47.836 INFO > Load experiment definition tables/files 09Nov11|10:47:48.248 INFO > Preload user defined function
- connecting to the FieldTrip buffer or [.DocsSectionsParallelMode#SecClients clients]
09Nov11|10:47:39.186 INFO > Initialize streaming from simulated data to: buffer://localhost:1975 09Nov11|10:47:44.855 INFO > Initialize reading from [[FieldTrip|Field Trip]] buffer: localhost:1975:biosemi_active2 09Mar11|16:14:08.347 INFO > Read from block settings: stim = localhost 09Mar11|16:14:08.350 INFO > server socket for lab 1, client stim, is connected to 127.0.0.1 (localhost), port 5001
Expanded Actions table
In addition, the log file always contains the [.DocsSectionsPlugIns#TableExpansion expanded] [.DocsSectionsBuildingExperiments#SecActions Actions table]. Although it looks a bit messy, it has the exact same content as the Actions table in your .edt or .xls file.
09Nov11|10:47:48.241 INFO > Combined complete experiment definition table:
marker time function feval looptick client stimsequence character sequence_count epoch_count fig
BS_INIT EVENT bs_send_buffer_marker('init_sequence','eeg',0,'now') [] [] 0 [] []
init_sequence EVENT initSequence(), bs_send_buffer_marker('next_sequence','eeg',0,'now') put
next_sequence EVENT nextSequence() get $self+1,get get,put
start_sequence button_1 displayString(''), bs_send_buffer_marker('next_epoch','eeg',0,'now') get get 0 get
next_epoch EVENT nextEpoch() get put get $self+1,get
proc_epoch EVENT displayString(), bs_send_buffer_marker('next_epoch','eeg',0.25,'now') get get
proc_epoch DATA bs_disp('process the data')
end_sequence EVENT bs_send_buffer_marker('next_sequence','eeg',1,'now')
button_1 EVENT
BS_QUIT EVENT bs_abort_experiment()
BS_ABORT EVENT bs_abort_experiment()
BS_EXIT EVENT bs_stop_experiment()
BrainStream processing
The onset of BrainStream processing is indicated by the line:
09Nov11|10:47:49.132 INFO > Start of Brainstream processing, initialize block
In the following section of the log file, each line of asterisks separates actions belonging to different [.DocsSectionsImportantConcepts#SecEvents events]. The name of the event is shown in brackets.
Action execution
In the example experiment of this log file, the BS_INIT marker triggered the modification of three user defined variables and the execution of a function. According to the [.DocsSectionsTableHandling fixed order] in which BrainStream executes actions, first the modification actions are completed and then the function is executed. This is the information in the log file:
09Nov11|10:47:49.155 INFO > '''***''' ( BS_INIT) '''*************************************************************''' 09Nov11|10:47:49.156 INFO > 9.80 (eeg:#1.00) 9.80 10.66 act: modvar (t=EVENT) BS_INIT 09Nov11|10:47:49.160 INFO > 9.80 (eeg:#1.00) 9.80 10.67 act: exefnc (t=EVENT) BS_INIT
The first number in each row specifies the time at which the marker arrives. Between parentheses, the corresponding sample numbers of the data from different data sources are given. In this case, there is only one data source, which is called 'eeg'. The sample at which the BS_INIT marker arrives is given sample number 1.
The second number specifies the time at which the actions described in this line of the log file were scheduled to take place, whereas the third number specifies the time at which the action actually was executed. In the Actions table of the example experiment, all actions for the BS_INIT marker were scheduled for execution at time point EVENT, that is, as soon as the marker arrives. Thus, the scheduled time point is equal to the time of marker arrival. The third row shows that the modification actions took place 860 ms after the scheduled time, followed by the function execution 870 ms after the scheduled time.
The fourth column shows the [.DocsSectionsTableHandling#ActionType type] of action that is executed: retrieving variable content (getvar), modifying variable content (modvar), executing functions (exefnc), or storing variable content (putvar). The fifth column shows the time point of the action as specified in the Actions table. The last column shows again the name of the marker that triggers the action.
Data selection
In the example experiment, each time the proc_epoch marker arrived, variable content was retrieved from the global variables and two functions were executed. In addition, one second of data was selected from the data source called 'eeg'. When the data had been selected, a third function was executed.
In this experiment, the first proc_epoch marker arrived at time 20.64, or EEG sample number 2776. Immediately, content of variables was retrieved (getvar) and the functions were executed (exefnc):
09Nov11|10:47:59.161 INFO > '''***''' ( proc_epoch) '''*************************************************************''' 09Nov11|10:47:59.161 INFO > 20.64 (eeg:#2776.00) 20.64 20.67 act: getvar (t=EVENT) proc_epoch 09Nov11|10:47:59.163 INFO > 20.64 (eeg:#2776.00) 20.64 20.67 act: exefnc (t=EVENT) proc_epoch
As we wanted to select one second of data, starting at the onset of marker proc_epoch, the execution of the last function could not take place before one second had elapsed. The log file indeed shows that one second after event onset, data was selected and the function was executed:
09Nov11|10:48:00.151 INFO > '''***''' ( proc_epoch) '''*************************************************************''' 09Nov11|10:48:00.152 INFO > 20.64 (eeg:#2776.00) 21.64 21.66 act: exefnc (t=DATA, eeg:#2776-#3031) proc_epoch
The time of event onset is the same as for the first two actions (20.64 seconds or EEG sample number 2776). The scheduled time for the execution of the function was one second after event onset (21.64 seconds), and the actual execution time was 20 ms later (21.66 seconds). In the next column, we see that a piece of data with sample numbers 2776 to 3031 has been selected from the EEG data source.
This example illustrates the point that although al actions following a line of asterisks belong to the same event, it is not necessarily the case that all actions belonging to the same event are listed under one and the same line of asterisks in the log file. In this experiment, three next_epoch and proc_epoch markers arrive before the last action of the first proc_epoch marker is executed:
09Nov11|10:47:59.161 INFO > '''***''' ( proc_epoch) '''*************************************************************''' 09Nov11|10:47:59.161 INFO > 20.64 (eeg:#2776.00) 20.64 20.67 act: getvar (t=EVENT) proc_epoch 09Nov11|10:47:59.163 INFO > 20.64 (eeg:#2776.00) 20.64 20.67 act: exefnc (t=EVENT) proc_epoch 09Nov11|10:47:59.435 INFO > '''***''' ( next_epoch) '''*************************************************************''' 09Nov11|10:47:59.436 INFO > 20.93 (eeg:#2850.00) 20.93 20.94 act: modvar (t=EVENT) next_epoch 09Nov11|10:47:59.438 INFO > 20.93 (eeg:#2850.00) 20.93 20.95 act: getvar (t=EVENT) next_epoch 09Nov11|10:47:59.439 INFO > 20.93 (eeg:#2850.00) 20.93 20.95 act: exefnc (t=EVENT) next_epoch 09Nov11|10:47:59.442 INFO > 20.93 (eeg:#2850.00) 20.93 20.95 act: putvar (t=EVENT) next_epoch . . . 09Nov11|10:48:00.151 INFO > '''***''' ( proc_epoch) '''*************************************************************''' 09Nov11|10:48:00.152 INFO > 20.64 (eeg:#2776.00) 21.64 21.66 act: exefnc (t=DATA, eeg:#2776-#3031) proc_epoch
In the log file, you can identify actions that belong to the same event by looking at the time of event onset, i.e. the first number that is specified in a row. You can see that the actions described in the two sections of the proc_epoch marker belong to the same event, because the time point of event onset is 20.64 in both cases.
Error messages
If something goes wrong during your experiment, error messages are shown on the screen. You can find these error messages in the log file as well. Error messages usually appear at the end of the log file, because processing is interrupted by the error.
An example:
09Mar11|16:14:11.221 INFO > Read from block settings: [[ReferenceFolder|Reference Folder]] = /Volumes/BCI_Stims/own_experiments/visual/Hexospell Reference to non-existent field 'layer16'. Error in :mkSymbolsHex, line : 41 Error in :ExecFncs, line : 34 Error in :ProcessEvents/action_execfnc, line : 393 Error in :ProcessEvents, line : 113 Error in :RunBCI3, line : 99 Error in :BCI, line : 50 Error in :brainstream_block, line : 35 Error in :StartBrainStream/LaunchBCIApplication, line : 206 Error in :StartBrainStream/pushbuttonStart_Callback, line : 335