Log file

Generate current PDF

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 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 this log file as an example. The log file belongs to the experiment described 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 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 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 bs_msg and 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 block file
    09Nov11|10:47:46.593 INFO >   Read from block settings: TriggerSource = default
    09Nov11|10:47:46.593 INFO >   Default used for TriggerDef (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 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 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 expanded 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 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 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 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 = /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

Topic revision: r13 - 16 Dec 2011 - 10:59:55 - MarjoleinVanDerWaal
BrainStreamDocs.DocsSectionsLogFile moved from BrainStream.DocsSectionsLogFile on 14 Nov 2011 - 09:55 by MarjoleinVanDerWaal - put it back
 
This site is powered by the TWiki collaboration platformCopyright © by the contributing authors. All material on this collaboration platform is the property of the contributing authors.
Ideas, requests, problems regarding TWiki? Send feedback