BrainStreamLogFile - Revision history

Wiki-admin at 13:41, 21 September 2018

2018-09-21T13:41:05Z

Wiki-admin at 12:41, 21 September 2018

2018-09-21T12:41:52Z

Wiki-admin: /* Log file */

2018-09-21T12:39:06Z

Log file

Wiki-admin: Created page with " =Log file = TOC BrainStream creates a log file for each block of your experiment. The log file gives an overview of everything that happened during your e..."

2018-09-21T12:10:55Z

Created page with " =Log file = __TOC__ BrainStream creates a log file for each block of your experiment. The log file gives an overview of everything that happened during your e..."

New page

=Log file =
__TOC__

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 [[BrainStreamExampleLogFile|this]] 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:
<pre>09Nov11|10:47:38.928 INFO ></pre>

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 <tt>[.DocsSectionsProgrmmersGuide#bs_msg bs_msg]</tt> and <tt>[.DocsSectionsProgrmmersGuide#bs_warn bs_warn]</tt> 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]<br /><pre>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</pre>
* loading files or functions<br /><pre>09Nov11|10:47:47.836 INFO > Load experiment definition tables/files
09Nov11|10:47:48.248 INFO > Preload user defined function</pre>
* connecting to the FieldTrip buffer or [.DocsSectionsParallelMode#SecClients clients]<br /><pre>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</pre>
== 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.
<pre>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() </pre>

== BrainStream processing ==

The onset of BrainStream processing is indicated by the line:
<pre>09Nov11|10:47:49.132 INFO > Start of Brainstream processing, initialize block </pre>

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:
<pre>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
</pre>

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):
<pre>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 </pre>

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:
<pre>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
</pre>

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:
<pre>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 </pre>

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:
<pre>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
</pre>

@@ Line 5: / Line 5: @@
 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 [[BrainStreamExampleLogFile|this]] log file as an example. The log file belongs to the experiment described [File:BrainStreamDocs_Log-09Nov2011-10h47m38s.docx|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 [[File:BrainStreamDocs_Log-09Nov2011-10h47m38s.docx|this]] log file as an example. The log file belongs to the experiment described [.DocsSectionsExampleSentences here].
 == Date and time ==

@@ Line 3: / Line 3: @@
 __TOC__
-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.
+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 [[BrainStreamPathsFolders#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|this]] log file as an example. The log file belongs to the experiment described [.DocsSectionsExampleSentences 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 [[File:BrainStreamDocs_Log-09Nov2011-10h47m38s.docx|this]] log file as an example. The log file belongs to the experiment described [[BrainStreamExampleSentences|here]].
 == Date and time ==
@@ Line 12: / Line 12: @@
 <pre>09Nov11|10:47:38.928 INFO ></pre>
-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.
+Date and time are derived from the computer which executes the actions. Note that if you are using [[BrainStreamParallelMode#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 <tt>[.DocsSectionsProgrmmersGuide#bs_msg bs_msg]</tt> and <tt>[.DocsSectionsProgrmmersGuide#bs_warn bs_warn]</tt> 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 [[BrainStreamBlockFile#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 <tt>[[BrainStreamProgrmmersGuide#bs_msg|bs_msg]]</tt> and <tt>[[BrainStreamProgrmmersGuide#bs_warn|bs_warn]]</tt> 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]<br />
+* reading settings from the [[BrainStreamBuildingExperiments#SecBlock|block file]]<br />
 <pre>
 Nov11|10:47:46.593 INFO >	Read from block settings: [[TriggerSource|Trigger Source]] = default
@@ Line 28: / Line 28: @@
 Nov11|10:47:48.248 INFO >	Preload user defined function
 </pre>
-* connecting to the FieldTrip buffer or [.DocsSectionsParallelMode#SecClients clients]<br />
+* connecting to the FieldTrip buffer or [[BrainStreamParallelMode#SecClients|clients]]<br />
 <pre>
 Nov11|10:47:39.186 INFO >	Initialize streaming from simulated data to: buffer://localhost:1975
@@ Line 38: / Line 38: @@
 == 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.
+In addition, the log file always contains the [.DocsSectionsPlugIns#TableExpansion expanded] [[BrainStreamBuildingExperiments#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.
 <pre>09Nov11|10:47:48.241 INFO >	Combined complete experiment definition table:
 marker	time	function	feval	looptick	client	stimsequence	character	sequence_count	epoch_count	fig
@@ Line 59: / Line 59: @@
 <pre>09Nov11|10:47:49.132 INFO >	Start of Brainstream processing, initialize block </pre>
-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.
+In the following section of the log file, each line of asterisks separates actions belonging to different [[BrainStreamImportantConcepts#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:
+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 [[BrainStreamTableHandling|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:
 <pre>09Nov11|10:47:49.155 INFO >	'''***''' (                  BS_INIT) '''*************************************************************'''
 Nov11|10:47:49.156 INFO >	  9.80 (eeg:#1.00)     9.80    10.66	act: modvar	(t=EVENT)	BS_INIT
@@ Line 72: / Line 72: @@
 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.
+The fourth column shows the [[BrainStreamTableHandling#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 ===

@@ Line 5: / Line 5: @@
 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 [[BrainStreamExampleLogFile|this]] log file as an example. The log file belongs to the experiment described [.DocsSectionsExampleSentences 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 [[BrainStreamExampleLogFile|this]] log file as an example. The log file belongs to the experiment described [File:BrainStreamDocs_Log-09Nov2011-10h47m38s.docx|here].
 == Date and time ==
@@ Line 18: / Line 18: @@
 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]<br /><pre>09Nov11|10:47:46.593 INFO >	Read from block settings: [[TriggerSource|Trigger Source]] = default
+* reading settings from the [.DocsSectionsBuildingExperiments#SecBlock block file]<br />
-Nov11|10:47:46.593 INFO >	Default used for [[TriggerDef|Trigger Def]] (failed reading from block settings</pre>
+<pre>
-* loading files or functions<br /><pre>09Nov11|10:47:47.836 INFO >	Load experiment definition tables/files
+Nov11|10:47:46.593 INFO >	Read from block settings: [[TriggerSource|Trigger Source]] = default
-Nov11|10:47:48.248 INFO >	Preload user defined function</pre>
+Nov11|10:47:46.593 INFO >	Default used for [[TriggerDef|Trigger Def]] (failed reading from block settings
-* connecting to the FieldTrip buffer or [.DocsSectionsParallelMode#SecClients clients]<br /><pre>09Nov11|10:47:39.186 INFO >	Initialize streaming from simulated data to: buffer://localhost:1975
+</pre>
 Nov11|10:47:44.855 INFO >	Initialize reading from [[FieldTrip|Field Trip]] buffer: localhost:1975:biosemi_active2
 Mar11|16:14:08.347 INFO >	Read from block settings: stim = localhost
-Mar11|16:14:08.350 INFO >	server socket for lab 1, client stim, is connected to 127.0.0.1 (localhost), port 5001</pre>
+Mar11|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 ==

BrainStreamLogFile - Revision history

Wiki-admin at 13:41, 21 September 2018

Wiki-admin at 12:41, 21 September 2018

Wiki-admin: /* Log file */

Wiki-admin: Created page with " =Log file = __TOC__ BrainStream creates a log file for each block of your experiment. The log file gives an overview of everything that happened during your e..."

Wiki-admin: Created page with " =Log file = TOC BrainStream creates a log file for each block of your experiment. The log file gives an overview of everything that happened during your e..."