Thanks again, Desmanto. I appreciate that it can be hard to resolve or understand an issue when all you have are some text messages.
I have resolved my problem for logging by reworking my scripts. Perhaps if I show you the working version, you might understand what I was trying to get at.
I perform my logging using a set of standardized actions. The first one,
Set up logging values initializes the variables that I use and is typically executed when Automagic is first started:
Code: Select all
<action type="script">
<useDefaultName>false</useDefaultName>
<name>Set up logging values </name>
<script>global_LogIndent = " ";
global_LogFlowStart='logVar=reverse(sort(findAll(join(getVariableNames(), ","), "logVar_\\\\d+"), true, true));if(length(logVar)==0){logCaller=trigger+" trigger";}else{logCaller=getValue(logVar[0], null)[0];};logPos=length(global_LogIndent) - 1;logVar="logVar_{logPos,numberformat,000}";setValue(logVar, newList(flow_name, logPos));global_LogIndent=left(global_LogIndent, logPos)+"<"+substring(global_LogIndent, logPos);logPrefix="{getDate(),dateformat,yyyy.MM.dd HH:mm:ss.SSS}{global_LogIndent}{getValue(logVar,null)[0]} called by {logCaller}";global_LogIndent=replace(global_LogIndent, "<", "|");{logPrefix}';
global_LogFlowMsg='logVar=reverse(sort(findAll(join(getVariableNames(), ","), "logVar_\\\\d+"), true, true))[0];logPos=getValue(logVar, null)[1];logPrefix="{getDate(),dateformat,yyyy.MM.dd HH:mm:ss.SSS}{left(global_LogIndent, logPos)}»{substring(global_LogIndent, logPos+1)}{getValue(logVar, null)[0]}";';
global_LogFlowEnd='logVar=reverse(sort(findAll(join(getVariableNames(), ","), "logVar_\\\\d+"), true, true))[0];logPos=getValue(logVar, null)[1];global_LogIndent="{left(global_LogIndent, logPos)}>{substring(global_LogIndent, logPos+1)}";logPrefix="{getDate(),dateformat,yyyy.MM.dd HH:mm:ss.SSS}{global_LogIndent}{getValue(logVar,null)[0]} ending";global_LogIndent=replace(left(global_LogIndent, length(global_LogIndent) - 1),">","°");while(endsWith(global_LogIndent, "°")){global_LogIndent=left(global_LogIndent, length(global_LogIndent) - 1);};global_LogIndent=global_LogIndent+" ";removeVariable(logVar);{logPrefix};';
</script>
Afterwards, flows typically begin by executing
Log flow start and end by executing
Log flow end:
Code: Select all
</action>
<action type="write_to_file">
<useDefaultName>false</useDefaultName>
<name>Log flow start</name>
<path>{global_primaryDirectory}/{global_deviceName}Log.txt</path>
<text>{eval(global_LogFlowStart)}
</text>
<append>true</append>
</action>
Code: Select all
<action type="write_to_file">
<useDefaultName>false</useDefaultName>
<name>Log flow end</name>
<path>{global_primaryDirectory}/{global_deviceName}Log.txt</path>
<text>{eval(global_LogFlowEnd)}
</text>
<append>true</append>
</action>
When a flow needs to log a message, it executes an action like this one:
Code: Select all
<action type="write_to_file">
<useDefaultName>false</useDefaultName>
<name> Log hello world</name>
<path>{global_primaryDirectory}/{global_deviceName}Log.txt</path>
<text>{eval(global_LogFlowMsg)} Hello World
</text>
<append>true</append>
</action>
The log file will look something like this:
2017.10.16 11:02:23.726 < Export Flows To Google Drive_ called by Manual trigger
2017.10.16 11:02:23.960 » Export Flows To Google Drive_ Exporting flows for group General to /storage/emulated/0/Automagic
2017.10.16 11:02:24.080 » Export Flows To Google Drive_ Exporting flows for group Tabitha to /storage/emulated/0/Automagic
2017.10.16 11:02:24.209 » Export Flows To Google Drive_ Exporting flows for group Utility to /storage/emulated/0/Automagic
2017.10.16 11:02:24.496 » Export Flows To Google Drive_ Uploading 3 groups to Google Drive
2017.10.16 11:02:25.950 |< MRP Status Check called by Manual trigger
2017.10.16 11:02:26.195 ||< _GetInternet called by MRP Status Check
2017.10.16 11:02:26.416 ||» _GetInternet WiFi connection to NML_Guest is active
2017.10.16 11:02:26.656 ||> _GetInternet ending
2017.10.16 11:02:27.614 |» MRP Status Check MRP error detected: MRP Status information was not pushed to Google Drive
2017.10.16 11:02:27.677 ||< _Present called by MRP Status Check
2017.10.16 11:02:28.177 ||» _Present showing [Monday's MRP process needs attention (11:2): MRP Status information was not pushed to Google Drive], require acknowledgement = [true]
2017.10.16 11:02:31.883 >|| Export Flows To Google Drive_ ending
2017.10.16 11:02:32.194 °|» _Present Text shown: operation result = [ok]
2017.10.16 11:02:32.500 °|> _Present ending
2017.10.16 11:02:32.575 °> MRP Status Check ending
2017.10.16 11:05:13.351 < Flow1 called by Manual trigger
2017.10.16 11:05:13.433 » Flow1 Hello World
2017.10.16 11:05:13.561 > Flow1 ending
where each flow puts a symbol in an assigned column:
< = flow start
| = flow still executing
» = flow is issuing a message
> = flow end
° = flow in this column ended earlier
This example show three flows running:
Export Flows To Google Drive_ starts first, then
MRP Status Check starts,
Export Flows To Google Drive_ finishes, followed by
MRP Status Check, and finally,
Flow1 starts and ends.