Difference: DocsSectionsLogFile (1 vs. 13)

Revision 1316 Dec 2011 - Main.MarjoleinVanDerWaal

Line: 1 to 1
 
META TOPICPARENT name="WebHome"
<---Start1--->

Log file

Line: 18 to 18
  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.
Changed:
<
<
The date and time can be followed either by INFO or WARN. This is related to the blocksetting screenoutputlevel. If screenoutputlevel 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 screenoutputlevel 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.
>
>
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

Revision 1214 Nov 2011 - Main.MarjoleinVanDerWaal

Line: 1 to 1
 
META TOPICPARENT name="WebHome"
<---Start1--->

Log file

Line: 16 to 16
 Each new line of the log file begins with a date and time:
09Nov11|10:47:38.928 INFO >
Changed:
<
<
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.
>
>
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.
 
Changed:
<
<
The date and time can be followed either by INFO or WARN. This is related to the block setting screenoutputlevel? . If screenoutputlevel 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 screenoutputlevel 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.
>
>
The date and time can be followed either by INFO or WARN. This is related to the blocksetting screenoutputlevel. If screenoutputlevel 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 screenoutputlevel 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

Line: 26 to 26
 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
Changed:
<
<
  • connecting to the FieldTrip buffer or clients
    09Nov11|10:47:39.186 INFO >   Initialize streaming from simulated data to: buffer://localhost:1975
>
>
  • 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

Revision 1114 Nov 2011 - Main.MarjoleinVanDerWaal

Line: 1 to 1
Changed:
<
<
META TOPICPARENT name="BrainStream.BrainStreamDocs"
>
>
META TOPICPARENT name="WebHome"
 
<---Start1--->

Log file

Revision 1014 Nov 2011 - Main.MarjoleinVanDerWaal

Line: 1 to 1
Changed:
<
<
META TOPICPARENT name="BrainStreamDocs"
>
>
META TOPICPARENT name="BrainStream.BrainStreamDocs"
 
<---Start1--->
Changed:
<
<

Log file

>
>

Log file

 
Changed:
<
<
Generate current PDF
>
>
Generate current PDF
 
Line: 126 to 126
 -->

META FILEATTACHMENT attachment="log-09Nov2011-10h47m38s.txt" attr="" comment="" date="1320837804" name="log-09Nov2011-10h47m38s.txt" path="log-09Nov2011-10h47m38s.txt" size="41366" stream="log-09Nov2011-10h47m38s.txt" tmpFilename="/var/tmp/CGItemp53996" user="MarjoleinVanDerWaal" version="1"
Added:
>
>
META TOPICMOVED by="MarjoleinVanDerWaal" date="1321264516" from="BrainStream.DocsSectionsLogFile" to="BrainStreamDocs.DocsSectionsLogFile"

Revision 910 Nov 2011 - Main.MarjoleinVanDerWaal

Line: 1 to 1
 
META TOPICPARENT name="BrainStreamDocs"
Changed:
<
<

Log file

>
>
<---Start1--->

Log file

  Generate current PDF
Line: 117 to 118
 Error in :StartBrainStream/pushbuttonStart_Callback, line : 335
Added:
>
>
<---End1--->

<-- 
  • Access control
    • Set DENYTOPICVIEW =
-->
 
META FILEATTACHMENT attachment="log-09Nov2011-10h47m38s.txt" attr="" comment="" date="1320837804" name="log-09Nov2011-10h47m38s.txt" path="log-09Nov2011-10h47m38s.txt" size="41366" stream="log-09Nov2011-10h47m38s.txt" tmpFilename="/var/tmp/CGItemp53996" user="MarjoleinVanDerWaal" version="1"

Revision 809 Nov 2011 - Main.MarjoleinVanDerWaal

Line: 1 to 1
 
META TOPICPARENT name="BrainStreamDocs"

Log file

Added:
>
>
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.

Revision 709 Nov 2011 - Main.MarjoleinVanDerWaal

Line: 1 to 1
 
META TOPICPARENT name="BrainStreamDocs"

Log file

Line: 6 to 6
  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.
Changed:
<
<
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.
>
>
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:

Changed:
<
<
01Nov11|09:09:15.278 INFO >
>
>
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.
Changed:
<
<
The date and time can be followed either by INFO or WARN. This is related to the block setting screenoutputlevel? . If screenoutputlevel 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 screenoutputlevel 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.
>
>
The date and time can be followed either by INFO or WARN. This is related to the block setting screenoutputlevel? . If screenoutputlevel 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 screenoutputlevel 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

Changed:
<
<
  • reading settings from the block file
    01Nov11|09:09:39.403 INFO >   Read from block settings: TriggerSource = default
    01Nov11|09:09:39.404 INFO >   Default used for TriggerDef (failed reading from block settings)
  • loading files or functions
    01Nov11|09:09:40.762 INFO >   Load experiment definition tables/files
    01Nov11|09:09:44.422 INFO >   Preload user defined functions
  • connecting to the FieldTrip buffer or clients
    01Nov11|09:09:15.278 INFO >   Initialize streaming from simulated data to: buffer://localhost:1975
    01Nov11|09:09:35.420 INFO >   Initialize reading from FieldTrip buffer: localhost:1975:biosemi_active2
>
>
  • 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.

Changed:
<
<
01Nov11|09:09:44.354 INFO >   Combined complete experiment definition table:
>
>
09Nov11|10:47:48.241 INFO >   Combined complete experiment definition table:
 marker time function feval looptick client stimsequence character sequence_count epoch_count fig
Changed:
<
<
BS_INIT EVENT bs_insert_marker('init_sequence',0) [] [] 0 [] [] init_sequence EVENT initSequence(), bs_insert_marker('next_sequence',0) put
>
>
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
Changed:
<
<
start_sequence button_1 displayString(''), bs_insert_marker('next_epoch',0) get get 0 get
>
>
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
Changed:
<
<
proc_epoch EVENT displayString(), bs_insert_marker('next_epoch',0.25) get 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')
Changed:
<
<
end_sequence EVENT bs_insert_marker('next_sequence',1)
>
>
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()
Line: 49 to 49
 

BrainStream processing

The onset of BrainStream processing is indicated by the line:

Changed:
<
<
01Nov11|09:09:46.807 INFO >   Start of Brainstream processing, initialize block 
>
>
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:

Changed:
<
<
01Nov11|09:09:46.953 INFO >   ***** (                  BS_INIT) ***************************************************************
01Nov11|09:09:46.960 INFO >    30.26 (eeg:#0.00)    30.26    32.67   act: modvar   (t=EVENT)   BS_INIT   
01Nov11|09:09:46.978 INFO >    30.26 (eeg:#0.00)    30.26    32.69   act: exefnc   (t=EVENT)   BS_INIT     
>
>
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    
 
Changed:
<
<
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 that arrives at the arrival of the BS_INIT marker is given sample number 0.
>
>
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.
 
Changed:
<
<
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 410 ms after the scheduled time, followed by the function execution 430 ms after the scheduled time.
>
>
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

Changed:
<
<
In the example experiment, each time the proc_epoch marker arrived, variable content is retrieved from the global variables and two functions are executed. In addition, one second of data is selected from the data source called 'eeg'. When the data has been selected, a third function is executed.
>
>
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.
 
Changed:
<
<
In this experiment, the first proc_epoch marker arrived at time 57.06, or EEG sample number 6860. Immediately, content of variables was retrieved (getvar) and the functions were executed (exefnc):
01Nov11|09:10:11.688 INFO >   ***** (               proc_epoch) ***************************************************************
01Nov11|09:10:11.689 INFO >    57.06 (eeg:#6860.00)    57.06    57.41   act: getvar   (t=EVENT)   proc_epoch   
01Nov11|09:10:11.691 INFO >    57.06 (eeg:#6860.00)    57.06    57.41   act: exefnc   (t=EVENT)   proc_epoch   
>
>
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:
Changed:
<
<
01Nov11|09:10:12.479 INFO >   ***** (               proc_epoch) ***************************************************************
01Nov11|09:10:12.481 INFO >    57.06 (eeg:#6860.00)    58.06    58.20   act: exefnc   (t=DATA, eeg:#6860-#7115)   proc_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 
 
Changed:
<
<
The time of event onset is the same as for the first two actions (57.06 seconds or EEG sample number 6860). The scheduled time for the execution of the function was one second after event onset (58.06 seconds), and the actual execution time was 140 ms later (58.20 seconds). In the next column, we see that a piece of data with sample numbers 6860 to 7115 has been selected from the EEG data source.
>
>
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:
Changed:
<
<
01Nov11|09:10:11.688 INFO >   ***** (               proc_epoch) ***************************************************************
01Nov11|09:10:11.689 INFO >    57.06 (eeg:#6860.00)    57.06    57.41   act: getvar   (t=EVENT)   proc_epoch   
01Nov11|09:10:11.691 INFO >    57.06 (eeg:#6860.00)    57.06    57.41   act: exefnc   (t=EVENT)   proc_epoch   
01Nov11|09:10:11.736 INFO >   ***** (               next_epoch) ***************************************************************
01Nov11|09:10:11.737 INFO >    57.31 (eeg:#6924.00)    57.31    57.46   act: modvar   (t=EVENT)   next_epoch   
01Nov11|09:10:11.739 INFO >    57.31 (eeg:#6924.00)    57.31    57.46   act: getvar   (t=EVENT)   next_epoch   
01Nov11|09:10:11.740 INFO >    57.31 (eeg:#6924.00)    57.31    57.46   act: exefnc   (t=EVENT)   next_epoch   
01Nov11|09:10:11.742 INFO >    57.31 (eeg:#6924.00)    57.31    57.46   act: putvar   (t=EVENT)   next_epoch   
>
>
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      
  . . .
Changed:
<
<
01Nov11|09:10:12.479 INFO > *** ( proc_epoch) ************************************************************* 01Nov11|09:10:12.481 INFO > 57.06 (eeg:#6860.00) 58.06 58.20 act: exefnc (t=DATA, eeg:#6860-#7115) 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 57.06 in both cases.
>
>
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
 
 
Changed:
<
<
META FILEATTACHMENT attachment="log-01Nov2011-09h09m14s.txt" attr="" comment="" date="1320836631" name="log-01Nov2011-09h09m14s.txt" path="log-01Nov2011-09h09m14s.txt" size="43090" stream="log-01Nov2011-09h09m14s.txt" tmpFilename="/var/tmp/CGItemp53735" user="MarjoleinVanDerWaal" version="1"
>
>
META FILEATTACHMENT attachment="log-09Nov2011-10h47m38s.txt" attr="" comment="" date="1320837804" name="log-09Nov2011-10h47m38s.txt" path="log-09Nov2011-10h47m38s.txt" size="41366" stream="log-09Nov2011-10h47m38s.txt" tmpFilename="/var/tmp/CGItemp53996" user="MarjoleinVanDerWaal" version="1"

Revision 609 Nov 2011 - Main.MarjoleinVanDerWaal

Line: 1 to 1
 
META TOPICPARENT name="BrainStreamDocs"

Log file

Line: 6 to 6
  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.
Changed:
<
<
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 a log file of the example experiment described here.
>
>
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

Line: 15 to 15
  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.
Changed:
<
<
The date and time can be followed either by INFO or WARN. This is related to the block setting screenoutputlevel? . If screenoutputlevel is set to INFO, all information in INFO and WARN lines of the log file will also be shown in the Matlab command window during the experiment. If screenoutputlevel is set to WARNING, only the WARN lines of the log file are 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.
>
>
The date and time can be followed either by INFO or WARN. This is related to the block setting screenoutputlevel? . If screenoutputlevel 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 screenoutputlevel 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

Line: 94 to 94
  . 01Nov11|09:10:12.479 INFO > *** ( proc_epoch) ************************************************************* 01Nov11|09:10:12.481 INFO > 57.06 (eeg:#6860.00) 58.06 58.20 act: exefnc (t=DATA, eeg:#6860-#7115) 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 57.06 in both cases. \ No newline at end of file
Added:
>
>
META FILEATTACHMENT attachment="log-01Nov2011-09h09m14s.txt" attr="" comment="" date="1320836631" name="log-01Nov2011-09h09m14s.txt" path="log-01Nov2011-09h09m14s.txt" size="43090" stream="log-01Nov2011-09h09m14s.txt" tmpFilename="/var/tmp/CGItemp53735" user="MarjoleinVanDerWaal" version="1"

Revision 504 Nov 2011 - Main.PhilipVanDenBroek

Line: 1 to 1
 
META TOPICPARENT name="BrainStreamDocs"

Log file

Line: 59 to 59
 01Nov11|09:09:46.960 INFO > 30.26 (eeg:#0.00) 30.26 32.67 act: modvar (t=EVENT) BS_INIT 01Nov11|09:09:46.978 INFO > 30.26 (eeg:#0.00) 30.26 32.69 act: exefnc (t=EVENT) BS_INIT
Changed:
<
<
The first number in each row specifies the time at which the marker arrives. Between brackets, 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 that arrives at the arrival of the BS_INIT marker is given sample number 0.
>
>
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 that arrives at the arrival of the BS_INIT marker is given sample number 0.
  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 410 ms after the scheduled time, followed by the function execution 430 ms after the scheduled time.

Revision 401 Nov 2011 - Main.MarjoleinVanDerWaal

Line: 1 to 1
 
META TOPICPARENT name="BrainStreamDocs"

Log file

Line: 15 to 15
  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.
Changed:
<
<
The date and time can be followed either by INFO or WARN. This is related to the block setting screenoutputlevel? . If screenoutputlevel is set to INFO, all information in INFO and WARN lines of the log file will also be shown in the Matlab command window during the experiment. If screenoutputlevel is set to WARNING, only the WARN lines of the log file are 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.
>
>
The date and time can be followed either by INFO or WARN. This is related to the block setting screenoutputlevel? . If screenoutputlevel is set to INFO, all information in INFO and WARN lines of the log file will also be shown in the Matlab command window during the experiment. If screenoutputlevel is set to WARNING, only the WARN lines of the log file are 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

Revision 301 Nov 2011 - Main.MarjoleinVanDerWaal

Line: 1 to 1
 
META TOPICPARENT name="BrainStreamDocs"
Changed:
<
<

Log file

>
>

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 runfolder of your experiment.
Line: 11 to 13
 Each new line of the log file begins with a date and time:
01Nov11|09:09:15.278 INFO >
Changed:
<
<
This indicates the time at which the event described in the corresponding line happened. The date and time can be followed either by INFO or WARN. This corresponds to the block setting screenoutputlevel? . If this block setting is set to INFO, all information in INFO lines of the log file will also be shown in the Matlab command window during the experiment. If the block setting is set to WARNING, only the WARN lines of the log file are shown in the Matlab command window.
>
>
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 block setting screenoutputlevel? . If screenoutputlevel is set to INFO, all information in INFO and WARN lines of the log file will also be shown in the Matlab command window during the experiment. If screenoutputlevel is set to WARNING, only the WARN lines of the log file are 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

Changed:
<
<
The first part of the log file describes everything that happened before the onset of BrainStream processing, that is, before the BS_INIT marker. For example, you may find information about
>
>
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
    01Nov11|09:09:39.403 INFO >   Read from block settings: TriggerSource = default
    01Nov11|09:09:39.404 INFO >   Default used for TriggerDef (failed reading from block settings)
  • loading files or functions
    01Nov11|09:09:40.762 INFO >   Load experiment definition tables/files
Line: 24 to 28
  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
Added:
>
>

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.
01Nov11|09:09:44.354 INFO >   Combined complete experiment definition table:
Line: 46 to 51
 The onset of BrainStream processing is indicated by the line:
01Nov11|09:09:46.807 INFO >   Start of Brainstream processing, initialize block 
Changed:
<
<
In the following section, each line of * indicates the onset of a new event. The name of the event is shown in brackets. The first event is always BS_INIT.
>
>
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

Changed:
<
<
In the example experiment of this log file, the BS_INIT marker triggered the modification of three user defined variables and the execution of the bs_insert_marker function. According to the fixed order in which BrainStream executes actions, first the modification actions are completed (modvar) and then the function is executed (exefnc). This is the information in the log file:
>
>
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:
 
01Nov11|09:09:46.953 INFO >   ***** (                  BS_INIT) ***************************************************************
01Nov11|09:09:46.960 INFO >    30.26 (eeg:#0.00)    30.26    32.67   act: modvar   (t=EVENT)   BS_INIT   
Changed:
<
<
01Nov11|09:09:46.978 INFO > 30.26 (eeg:#0.00) 30.26 32.69 act: exefnc (t=EVENT) BS_INIT The first number in each row specifies the time of event onset. Between brackets, the corresponding sample number of the data is given. In this case, there is only one data source, called 'eeg'. The sample that arrives at the onset of the BS_INIT event is given sample number 0.
>
>
01Nov11|09:09:46.978 INFO > 30.26 (eeg:#0.00) 30.26 32.69 act: exefnc (t=EVENT) BS_INIT

The first number in each row specifies the time at which the marker arrives. Between brackets, 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 that arrives at the arrival of the BS_INIT marker is given sample number 0.

 
Added:
>
>
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 410 ms after the scheduled time, followed by the function execution 430 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

Changed:
<
<
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 function was executed.
>
>
In the example experiment, each time the proc_epoch marker arrived, variable content is retrieved from the global variables and two functions are executed. In addition, one second of data is selected from the data source called 'eeg'. When the data has been selected, a third function is executed.
  In this experiment, the first proc_epoch marker arrived at time 57.06, or EEG sample number 6860. Immediately, content of variables was retrieved (getvar) and the functions were executed (exefnc):
01Nov11|09:10:11.688 INFO >   ***** (               proc_epoch) ***************************************************************
01Nov11|09:10:11.689 INFO >    57.06 (eeg:#6860.00)    57.06    57.41   act: getvar   (t=EVENT)   proc_epoch   
01Nov11|09:10:11.691 INFO >    57.06 (eeg:#6860.00)    57.06    57.41   act: exefnc   (t=EVENT)   proc_epoch   
Changed:
<
<
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:
>
>
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:
 
01Nov11|09:10:12.479 INFO >   ***** (               proc_epoch) ***************************************************************
01Nov11|09:10:12.481 INFO >    57.06 (eeg:#6860.00)    58.06    58.20   act: exefnc   (t=DATA, eeg:#6860-#7115)   proc_epoch 

The time of event onset is the same as for the first two actions (57.06 seconds or EEG sample number 6860). The scheduled time for the execution of the function was one second after event onset (58.06 seconds), and the actual execution time was 140 ms later (58.20 seconds). In the next column, we see that a piece of data with sample numbers 6860 to 7115 has been selected from the EEG data source.

Changed:
<
<
This example illustrates the important point that actions belonging to the same event do not necessarily appear together in the log file. In this case, three next_epoch and proc_epoch markers arrive before the last action of the first proc_epoch marker is executed. 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.
>
>
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:
01Nov11|09:10:11.688 INFO >   ***** (               proc_epoch) ***************************************************************
01Nov11|09:10:11.689 INFO >    57.06 (eeg:#6860.00)    57.06    57.41   act: getvar   (t=EVENT)   proc_epoch   
01Nov11|09:10:11.691 INFO >    57.06 (eeg:#6860.00)    57.06    57.41   act: exefnc   (t=EVENT)   proc_epoch   
01Nov11|09:10:11.736 INFO >   ***** (               next_epoch) ***************************************************************
01Nov11|09:10:11.737 INFO >    57.31 (eeg:#6924.00)    57.31    57.46   act: modvar   (t=EVENT)   next_epoch   
01Nov11|09:10:11.739 INFO >    57.31 (eeg:#6924.00)    57.31    57.46   act: getvar   (t=EVENT)   next_epoch   
01Nov11|09:10:11.740 INFO >    57.31 (eeg:#6924.00)    57.31    57.46   act: exefnc   (t=EVENT)   next_epoch   
01Nov11|09:10:11.742 INFO >    57.31 (eeg:#6924.00)    57.31    57.46   act: putvar   (t=EVENT)   next_epoch   
   .
   .
   .
01Nov11|09:10:12.479 INFO >   ***** (               proc_epoch) ***************************************************************
01Nov11|09:10:12.481 INFO >    57.06 (eeg:#6860.00)    58.06    58.20   act: exefnc   (t=DATA, eeg:#6860-#7115)   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 57.06 in both cases.

Revision 201 Nov 2011 - Main.MarjoleinVanDerWaal

Line: 1 to 1
 
META TOPICPARENT name="BrainStreamDocs"

Log file

Line: 46 to 46
 The onset of BrainStream processing is indicated by the line:
01Nov11|09:09:46.807 INFO >   Start of Brainstream processing, initialize block 
Changed:
<
<
In the following section, each line of * indicates the onset of a new event. The name of the event is shown in brackets. The first event is always BS_INIT. In the example experiment of this log file, the BS_INIT marker triggered the modification of three user defined variables and the execution of the bs_insert_marker function. According to the fixed order in which BrainStream executes actions, first the modification actions are completed and then the function is executed. This can be seen in the log file:
>
>
In the following section, each line of * indicates the onset of a new event. The name of the event is shown in brackets. The first event is always BS_INIT.

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 the bs_insert_marker function. According to the fixed order in which BrainStream executes actions, first the modification actions are completed (modvar) and then the function is executed (exefnc). This is the information in the log file:

 
01Nov11|09:09:46.953 INFO >   ***** (                  BS_INIT) ***************************************************************
01Nov11|09:09:46.960 INFO >    30.26 (eeg:#0.00)    30.26    32.67   act: modvar   (t=EVENT)   BS_INIT   
Changed:
<
<
01Nov11|09:09:46.978 INFO > 30.26 (eeg:#0.00) 30.26 32.69 act: exefnc (t=EVENT) BS_INIT
>
>
01Nov11|09:09:46.978 INFO > 30.26 (eeg:#0.00) 30.26 32.69 act: exefnc (t=EVENT) BS_INIT The first number in each row specifies the time of event onset. Between brackets, the corresponding sample number of the data is given. In this case, there is only one data source, called 'eeg'. The sample that arrives at the onset of the BS_INIT event is given sample number 0.

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 function was executed.

In this experiment, the first proc_epoch marker arrived at time 57.06, or EEG sample number 6860. Immediately, content of variables was retrieved (getvar) and the functions were executed (exefnc):

01Nov11|09:10:11.688 INFO >   ***** (               proc_epoch) ***************************************************************
01Nov11|09:10:11.689 INFO >    57.06 (eeg:#6860.00)    57.06    57.41   act: getvar   (t=EVENT)   proc_epoch   
01Nov11|09:10:11.691 INFO >    57.06 (eeg:#6860.00)    57.06    57.41   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:

01Nov11|09:10:12.479 INFO >   ***** (               proc_epoch) ***************************************************************
01Nov11|09:10:12.481 INFO >    57.06 (eeg:#6860.00)    58.06    58.20   act: exefnc   (t=DATA, eeg:#6860-#7115)   proc_epoch 

The time of event onset is the same as for the first two actions (57.06 seconds or EEG sample number 6860). The scheduled time for the execution of the function was one second after event onset (58.06 seconds), and the actual execution time was 140 ms later (58.20 seconds). In the next column, we see that a piece of data with sample numbers 6860 to 7115 has been selected from the EEG data source.

This example illustrates the important point that actions belonging to the same event do not necessarily appear together in the log file. In this case, three next_epoch and proc_epoch markers arrive before the last action of the first proc_epoch marker is executed. 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.

Revision 101 Nov 2011 - Main.MarjoleinVanDerWaal

Line: 1 to 1
Added:
>
>
META TOPICPARENT name="BrainStreamDocs"

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 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 a log file of the example experiment described here.

Date and time

Each new line of the log file begins with a date and time:

01Nov11|09:09:15.278 INFO >

This indicates the time at which the event described in the corresponding line happened. The date and time can be followed either by INFO or WARN. This corresponds to the block setting screenoutputlevel? . If this block setting is set to INFO, all information in INFO lines of the log file will also be shown in the Matlab command window during the experiment. If the block setting is set to WARNING, only the WARN lines of the log file are shown in the Matlab command window.

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. For example, you may find information about

  • reading settings from the block file
    01Nov11|09:09:39.403 INFO >   Read from block settings: TriggerSource = default
    01Nov11|09:09:39.404 INFO >   Default used for TriggerDef (failed reading from block settings)
  • loading files or functions
    01Nov11|09:09:40.762 INFO >   Load experiment definition tables/files
    01Nov11|09:09:44.422 INFO >   Preload user defined functions
  • connecting to the FieldTrip buffer or clients
    01Nov11|09:09:15.278 INFO >   Initialize streaming from simulated data to: buffer://localhost:1975
    01Nov11|09:09:35.420 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

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.

01Nov11|09:09:44.354 INFO >   Combined complete experiment definition table:
marker   time   function   feval   looptick   client   stimsequence   character   sequence_count   epoch_count   fig
BS_INIT   EVENT   bs_insert_marker('init_sequence',0)            []   []   0   []   []
init_sequence   EVENT   initSequence(), bs_insert_marker('next_sequence',0)            put            
next_sequence   EVENT   nextSequence()            get      $self+1,get      get,put
start_sequence   button_1   displayString(''), bs_insert_marker('next_epoch',0)            get      get   0   get
next_epoch   EVENT   nextEpoch()            get   put   get   $self+1,get   
proc_epoch   EVENT   displayString(), bs_insert_marker('next_epoch',0.25)               get         get
proc_epoch   DATA   bs_disp('process the data')                        
end_sequence   EVENT   bs_insert_marker('next_sequence',1)                        
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:

01Nov11|09:09:46.807 INFO >   Start of Brainstream processing, initialize block 

In the following section, each line of * indicates the onset of a new event. The name of the event is shown in brackets. The first event is always BS_INIT. In the example experiment of this log file, the BS_INIT marker triggered the modification of three user defined variables and the execution of the bs_insert_marker function. According to the fixed order in which BrainStream executes actions, first the modification actions are completed and then the function is executed. This can be seen in the log file:

01Nov11|09:09:46.953 INFO >   ***** (                  BS_INIT) ***************************************************************
01Nov11|09:09:46.960 INFO >    30.26 (eeg:#0.00)    30.26    32.67   act: modvar   (t=EVENT)   BS_INIT   
01Nov11|09:09:46.978 INFO >    30.26 (eeg:#0.00)    30.26    32.69   act: exefnc   (t=EVENT)   BS_INIT   
 
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