Bugfix in timeout management of DynamicStringBuffer. Introduces new u…

…nit test for many logs in many consecutive cycles. fixes #4
bengeisler · Aug 31, 2023 · a158ac9 · a158ac9
1 parent 6b2ebf8
commit a158ac9
Show file tree

Hide file tree

Showing 8 changed files with 113 additions and 66 deletions.
diff --git a/TcLog.library b/TcLog.library
diff --git a/TcLog.sln b/TcLog.sln
@@ -61,26 +61,6 @@ Global
 		{41F52577-96F4-46B7-BDEF-F5A9C5753EA6}.Release|TwinCAT RT (x64).Build.0 = Release|Any CPU
 		{41F52577-96F4-46B7-BDEF-F5A9C5753EA6}.Release|TwinCAT RT (x86).ActiveCfg = Release|Any CPU
 		{41F52577-96F4-46B7-BDEF-F5A9C5753EA6}.Release|TwinCAT RT (x86).Build.0 = Release|Any CPU
-		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Debug|Any CPU.ActiveCfg = Debug|TwinCAT RT (x64)
-		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Debug|Any CPU.Build.0 = Debug|TwinCAT RT (x64)
-		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Debug|TwinCAT CE7 (ARMV7).ActiveCfg = Debug|TwinCAT CE7 (ARMV7)
-		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Debug|TwinCAT CE7 (ARMV7).Build.0 = Debug|TwinCAT CE7 (ARMV7)
-		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Debug|TwinCAT OS (ARMT2).ActiveCfg = Debug|TwinCAT OS (ARMT2)
-		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Debug|TwinCAT OS (ARMT2).Build.0 = Debug|TwinCAT OS (ARMT2)
-		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Debug|TwinCAT RT (x64).ActiveCfg = Debug|TwinCAT RT (x64)
-		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Debug|TwinCAT RT (x64).Build.0 = Debug|TwinCAT RT (x64)
-		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Debug|TwinCAT RT (x86).ActiveCfg = Debug|TwinCAT RT (x86)
-		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Debug|TwinCAT RT (x86).Build.0 = Debug|TwinCAT RT (x86)
-		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Release|Any CPU.ActiveCfg = Release|TwinCAT RT (x64)
-		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Release|Any CPU.Build.0 = Release|TwinCAT RT (x64)
-		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Release|TwinCAT CE7 (ARMV7).ActiveCfg = Release|TwinCAT CE7 (ARMV7)
-		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Release|TwinCAT CE7 (ARMV7).Build.0 = Release|TwinCAT CE7 (ARMV7)
-		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Release|TwinCAT OS (ARMT2).ActiveCfg = Release|TwinCAT OS (ARMT2)
-		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Release|TwinCAT OS (ARMT2).Build.0 = Release|TwinCAT OS (ARMT2)
-		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Release|TwinCAT RT (x64).ActiveCfg = Release|TwinCAT RT (x64)
-		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Release|TwinCAT RT (x64).Build.0 = Release|TwinCAT RT (x64)
-		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Release|TwinCAT RT (x86).ActiveCfg = Release|TwinCAT RT (x86)
-		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Release|TwinCAT RT (x86).Build.0 = Release|TwinCAT RT (x86)
 		{534B7BB3-9B49-4F2B-86CC-2317930EA23D}.Debug|Any CPU.ActiveCfg = Debug|TwinCAT RT (x64)
 		{534B7BB3-9B49-4F2B-86CC-2317930EA23D}.Debug|Any CPU.Build.0 = Debug|TwinCAT RT (x64)
 		{534B7BB3-9B49-4F2B-86CC-2317930EA23D}.Debug|TwinCAT CE7 (ARMV7).ActiveCfg = Debug|TwinCAT CE7 (ARMV7)
@@ -101,6 +81,26 @@ Global
 		{534B7BB3-9B49-4F2B-86CC-2317930EA23D}.Release|TwinCAT RT (x64).Build.0 = Release|TwinCAT RT (x64)
 		{534B7BB3-9B49-4F2B-86CC-2317930EA23D}.Release|TwinCAT RT (x86).ActiveCfg = Release|TwinCAT RT (x86)
 		{534B7BB3-9B49-4F2B-86CC-2317930EA23D}.Release|TwinCAT RT (x86).Build.0 = Release|TwinCAT RT (x86)
+		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Debug|Any CPU.ActiveCfg = Debug|TwinCAT RT (x64)
+		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Debug|Any CPU.Build.0 = Debug|TwinCAT RT (x64)
+		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Debug|TwinCAT CE7 (ARMV7).ActiveCfg = Debug|TwinCAT CE7 (ARMV7)
+		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Debug|TwinCAT CE7 (ARMV7).Build.0 = Debug|TwinCAT CE7 (ARMV7)
+		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Debug|TwinCAT OS (ARMT2).ActiveCfg = Debug|TwinCAT OS (ARMT2)
+		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Debug|TwinCAT OS (ARMT2).Build.0 = Debug|TwinCAT OS (ARMT2)
+		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Debug|TwinCAT RT (x64).ActiveCfg = Debug|TwinCAT RT (x64)
+		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Debug|TwinCAT RT (x64).Build.0 = Debug|TwinCAT RT (x64)
+		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Debug|TwinCAT RT (x86).ActiveCfg = Debug|TwinCAT RT (x86)
+		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Debug|TwinCAT RT (x86).Build.0 = Debug|TwinCAT RT (x86)
+		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Release|Any CPU.ActiveCfg = Release|TwinCAT RT (x64)
+		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Release|Any CPU.Build.0 = Release|TwinCAT RT (x64)
+		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Release|TwinCAT CE7 (ARMV7).ActiveCfg = Release|TwinCAT CE7 (ARMV7)
+		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Release|TwinCAT CE7 (ARMV7).Build.0 = Release|TwinCAT CE7 (ARMV7)
+		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Release|TwinCAT OS (ARMT2).ActiveCfg = Release|TwinCAT OS (ARMT2)
+		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Release|TwinCAT OS (ARMT2).Build.0 = Release|TwinCAT OS (ARMT2)
+		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Release|TwinCAT RT (x64).ActiveCfg = Release|TwinCAT RT (x64)
+		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Release|TwinCAT RT (x64).Build.0 = Release|TwinCAT RT (x64)
+		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Release|TwinCAT RT (x86).ActiveCfg = Release|TwinCAT RT (x86)
+		{67A5CD22-D1E6-4601-AC63-4CEBE4A64230}.Release|TwinCAT RT (x86).Build.0 = Release|TwinCAT RT (x86)
 	EndGlobalSection
 	GlobalSection(SolutionProperties) = preSolution
 		HideSolutionNode = FALSE

diff --git a/TcLogProj/TcLog/Helper functions/DynamicStringBuffer.TcPOU b/TcLogProj/TcLog/Helper functions/DynamicStringBuffer.TcPOU
@@ -98,7 +98,6 @@ VAR_INST
 	               	
 	fbFileClose    	 	: 	FB_FileClose;
 	fTrigFileClose		: 	F_TRIG;
-	tonTimeout			:	TON;
 END_VAR
 VAR CONSTANT
 	STATE_IDLE							:	UINT	:=	0;
@@ -143,18 +142,9 @@ CASE state OF
 	
 END_CASE
 
-(* Uncomment for cycle-specific usage of state machine & buffer usage
-
-ADSLOGSTR(ADSLOG_MSGTYPE_LOG, 
-	CONCAT('****DynamicStringBuffer.state:', 
-	CONCAT(UINT_TO_STRING(state),
-	CONCAT(', DynamicStringBuffer.hFile:', UINT_TO_STRING(hFile)))), '');
-
-ADSLOGSTR(ADSLOG_MSGTYPE_LOG, 
-			CONCAT('****Fifo: used ', 
-			CONCAT(UDINT_TO_STRING(Fifo.cbSize),
-			CONCAT(' of ', UDINT_TO_STRING(Fifo.cbBuffer)))), '');
-*)
+// Close file in case of error
+IF fbFileOpen.bError THEN state := STATE_CLOSE_FILE; END_IF
+IF fbFilePuts.bError THEN state := STATE_CLOSE_FILE; END_IF
 
 // Function blocks used in state machine
 fbFileOpen(
@@ -170,13 +160,9 @@ fTrigFilePuts(CLK := fbFilePuts.bBusy);
 
 fbFileClose(
 	sNetId := NET_ID, hFile := hFile, 
-	bExecute := (state = STATE_CLOSE_FILE) OR tonTimeout.Q, tTimeout := TIMEOUT);
+	bExecute := (state = STATE_CLOSE_FILE), tTimeout := TIMEOUT);
 fTrigFileClose(CLK := fbFileClose.bBusy);	
 
-// Timeout writing to file => close file
-tonTimeout(IN := state <> STATE_IDLE, PT:=TIMEOUT);	
-IF tonTimeout.Q THEN state := STATE_IDLE; END_IF
-
 
 // Error handling
 IF fbFileOpen.bError THEN
@@ -201,11 +187,24 @@ ELSE
 	Error.Info := '';
 END_IF
 
+(* Uncomment for cyclic logging of state machine, buffer usage & errors
+
+ADSLOGSTR(ADSLOG_MSGTYPE_LOG, 
+	CONCAT('****DynamicStringBuffer.state:', 
+	CONCAT(UINT_TO_STRING(state),
+	CONCAT(', DynamicStringBuffer.hFile:', UINT_TO_STRING(hFile)))), '');
+
+ADSLOGSTR(ADSLOG_MSGTYPE_LOG, 
+	CONCAT('****Fifo: used ', 
+	CONCAT(UDINT_TO_STRING(Fifo.cbSize),
+	CONCAT(' of ', UDINT_TO_STRING(Fifo.cbBuffer)))), '');
+	
 IF Error.Active THEN
 	ADSLOGSTR(ADSLOG_MSGTYPE_LOG, 
 		CONCAT('****DynamicStringBuffer.Error: ', Error.Info), 
 		'');	
-END_IF]]></ST>
+END_IF
+*)]]></ST>
       </Implementation>
     </Method>
     <Method Name="PopHead" Id="{1c3e8de3-af72-4def-8aba-61974c7aa041}">
@@ -278,21 +277,12 @@ END_IF]]></ST>
       <LineId Id="19" Count="1" />
       <LineId Id="129" Count="0" />
       <LineId Id="21" Count="8" />
-      <LineId Id="328" Count="0" />
-      <LineId Id="324" Count="0" />
-      <LineId Id="330" Count="0" />
-      <LineId Id="325" Count="2" />
-      <LineId Id="323" Count="0" />
-      <LineId Id="289" Count="3" />
-      <LineId Id="288" Count="0" />
-      <LineId Id="30" Count="0" />
+      <LineId Id="339" Count="0" />
+      <LineId Id="338" Count="0" />
+      <LineId Id="337" Count="0" />
+      <LineId Id="336" Count="0" />
       <LineId Id="329" Count="0" />
-      <LineId Id="31" Count="15" />
-      <LineId Id="161" Count="0" />
-      <LineId Id="160" Count="0" />
-      <LineId Id="163" Count="0" />
-      <LineId Id="168" Count="0" />
-      <LineId Id="47" Count="0" />
+      <LineId Id="31" Count="16" />
       <LineId Id="331" Count="0" />
       <LineId Id="48" Count="0" />
       <LineId Id="53" Count="3" />
@@ -302,11 +292,8 @@ END_IF]]></ST>
       <LineId Id="95" Count="0" />
       <LineId Id="100" Count="2" />
       <LineId Id="5" Count="0" />
-      <LineId Id="281" Count="0" />
-      <LineId Id="280" Count="0" />
-      <LineId Id="284" Count="1" />
-      <LineId Id="287" Count="0" />
-      <LineId Id="283" Count="0" />
+      <LineId Id="341" Count="17" />
+      <LineId Id="340" Count="0" />
     </LineIds>
     <LineIds Name="DynamicStringBuffer.PopHead">
       <LineId Id="5" Count="0" />

diff --git a/TcLogProj/TcLog/TcLog.plcproj b/TcLogProj/TcLog/TcLog.plcproj
@@ -16,9 +16,9 @@
     <Implicit_Jitter_Distribution>{d696fa89-a5b7-4359-9420-e6a3f2f66b93}</Implicit_Jitter_Distribution>
     <LibraryReferences>{e556042a-b034-4e51-bfa4-92060eb4b7b8}</LibraryReferences>
     <Company>Benedikt Geisler</Company>
-    <Released>false</Released>
+    <Released>true</Released>
     <Title>TcLog</Title>
-    <ProjectVersion>0.2.0</ProjectVersion>
+    <ProjectVersion>0.2.1</ProjectVersion>
     <CombineIds>false</CombineIds>
     <DefaultNamespace>TcLog</DefaultNamespace>
     <Author>Benedikt Geisler</Author>

diff --git a/TcLogProj/TcLog/Version/Global_Version.TcGVL b/TcLogProj/TcLog/Version/Global_Version.TcGVL
@@ -7,7 +7,7 @@
 // This function has been automatically generated from the project information.
 VAR_GLOBAL CONSTANT
 	{attribute 'const_non_replaced'}
-	stLibVersion_TcLog : ST_LibVersion := (iMajor := 0, iMinor := 2, iBuild := 0, iRevision := 0, nFlags := 0, sVersion := '0.2.0');
+	stLibVersion_TcLog : ST_LibVersion := (iMajor := 0, iMinor := 2, iBuild := 1, iRevision := 0, nFlags := 1, sVersion := '0.2.1');
 END_VAR
 ]]></Declaration>
   </GVL>

diff --git a/TcLogProj/TcLogTest/Helper functions/DynamicStringBuffer_TEST.TcPOU b/TcLogProj/TcLogTest/Helper functions/DynamicStringBuffer_TEST.TcPOU
@@ -23,13 +23,13 @@ VAR
 END_VAR
 
 VAR CONSTANT
-	CYCLES: UDINT := 30;
-	MESSAGES: UDINT := 30;
+	CYCLES: UDINT := 50;
+	MESSAGES: UDINT := 50;
 END_VAR
 
 VAR_INST
 	cycleCount: UDINT := 0;
-	LogsManyMessagesForManyCyclesLogger: TcLogCore(nBufferSize := 30*30*280); // cycles * messages * (max string length + fifo overhead (estimated))
+	LogsManyMessagesForManyCyclesLogger: TcLogCore(nBufferSize := 50*50*280); // cycles * messages * (max string length + fifo overhead (estimated))
 	logger: TcLog;
 END_VAR
 ]]></Declaration>
@@ -65,7 +65,7 @@ IF LEN(LogsManyMessagesForManyCyclesLogger.Error.Info) > 0 THEN
 	result := LogsManyMessagesForManyCyclesLogger.Error.Info;
 END_IF
 
-IF cycleCount > (CYCLES * MESSAGES * 4 + 10) THEN 
+IF cycleCount > (CYCLES * MESSAGES * 5 + 100) THEN 
 	AssertEquals(Expected := expected,
 				 Actual := result,
 				 Message := result);

diff --git a/TcLogProj/TcLogTest/NET/TestWrapper_NET.TcPOU b/TcLogProj/TcLogTest/NET/TestWrapper_NET.TcPOU
@@ -7,7 +7,7 @@ END_VAR
 VAR_OUTPUT
 END_VAR
 VAR
-	CoreLogger	:	TcLogCore(nBufferSize := 100000);
+	CoreLogger	:	TcLogCore(nBufferSize := 50*50*280);
 	Logger		:	TcLog;
 	error		:	ST_Error;
 	bFlushCache :   BOOL;
@@ -52,6 +52,10 @@ VAR
 	
 	Log_multiple_logs_in_one_cycle: BOOL;
 	Number_of_logs_per_cycle: DINT;
+	
+	Log_multiple_logs_in_multiple_cycles: BOOL;
+	Number_of_cycles: DINT;
+	_cycleCount: DINT := 1;
 END_VAR
 ]]></Declaration>
     <Implementation>
@@ -159,6 +163,23 @@ IF Log_multiple_logs_in_one_cycle THEN
 	Log_multiple_logs_in_one_cycle := FALSE;
 END_IF
 
+IF Log_multiple_logs_in_multiple_cycles THEN
+	IF _cycleCount <= Number_of_cycles THEN	
+		FOR i:= 1 TO DINT_TO_INT(Number_of_logs_per_cycle) DO
+			Logger
+				.AppendString('Logging multiple times per cycle. Cycle: ')
+				.AppendString(DINT_TO_STRING(_cycleCount))
+				.AppendString(' / Step: ')
+				.AppendString(INT_TO_STRING(i))
+				.Error('');
+		END_FOR
+		_cycleCount := _cycleCount + 1;
+	ELSE
+		_cycleCount := 1;
+		Log_multiple_logs_in_multiple_cycles := FALSE;
+	END_IF
+END_IF
+
 ]]></ST>
     </Implementation>
     <LineIds Name="TestWrapper_NET">
@@ -181,6 +202,16 @@ END_IF
       <LineId Id="207" Count="0" />
       <LineId Id="210" Count="0" />
       <LineId Id="204" Count="0" />
+      <LineId Id="264" Count="1" />
+      <LineId Id="276" Count="0" />
+      <LineId Id="266" Count="1" />
+      <LineId Id="278" Count="0" />
+      <LineId Id="282" Count="1" />
+      <LineId Id="279" Count="1" />
+      <LineId Id="269" Count="0" />
+      <LineId Id="286" Count="3" />
+      <LineId Id="277" Count="0" />
+      <LineId Id="263" Count="0" />
       <LineId Id="197" Count="0" />
       <LineId Id="2" Count="0" />
     </LineIds>

diff --git a/TcLogTest.NET/PersistingToFileSystem.cs b/TcLogTest.NET/PersistingToFileSystem.cs
@@ -287,5 +287,34 @@ public async void Log_multiple_times_in_one_cycle(int logCount, int waitTime)
             fixture.TcClient.DeleteVariableHandle(hRun);
             fixture.TcClient.DeleteVariableHandle(hLogCount);
         }
+
+        [Theory]
+        [InlineData(5, 5, 5_000)]
+        [InlineData(10, 10, 10_000)]
+        [InlineData(20, 20, 30_000)]
+        [InlineData(50, 50, 180_000)]
+        public async void Log_multiple_times_in_multiple_cycles(int cycleCount, int logCount, int waitTime)
+        {
+            uint hRun = fixture.TcClient.CreateVariableHandle(mut + ".Log_multiple_logs_in_multiple_cycles");
+            uint hCycleCount = fixture.TcClient.CreateVariableHandle(mut + ".Number_of_cycles");
+            uint hLogCount = fixture.TcClient.CreateVariableHandle(mut + ".Number_of_logs_per_cycle");
+
+            fixture.TcClient.WriteAny(hCycleCount, cycleCount);
+            fixture.TcClient.WriteAny(hLogCount, logCount);
+            fixture.TcClient.WriteAny(hRun, true);
+            await Task.Delay(waitTime);
+            var files = Directory.GetFiles(path);
+
+            var fileContent = File.ReadAllLines(files[0]);
+
+            Assert.Equal<int>(cycleCount * logCount, fileContent.Length);
+
+            fixture.TcClient.WriteAny(hCycleCount, 0);
+            fixture.TcClient.WriteAny(hLogCount, 0);
+            foreach (var f in files) File.Delete(f);
+            fixture.TcClient.DeleteVariableHandle(hRun);
+            fixture.TcClient.DeleteVariableHandle(hCycleCount);
+            fixture.TcClient.DeleteVariableHandle(hLogCount);
+        }
     }
 }