[Improve][AW-CCS][Main]

2020.09.28 / Folus Wen

Actions:
1. EVSE/Projects/AW-CCS/Apps/main.c CCS handshake timeout logic improve.
2. EVSE/Projects/AW-CCS/Apps/LCM/Module_LcmControl.c tranciever timeout extend to 500ms.
3. All debug info output format alignment.

Files:
1. As follow commit history

Image version: D0.38.XX.XXXX.XX
Image checksum: XXXXXXXX

Hardware PWB P/N : XXXXXXX
Hardware Version : XXXXXXX

EVSE/Modularization/Module_Upgrade.c

@@ -30,6 +30,7 @@ int storeLogMsg(const char *fmt, ...)
     char buffer[4096];
     time_t CurrentTime;
     struct tm *tm;
+    struct timeval tv;
     va_list args;
 
     va_start(args, fmt);
@@ -39,8 +40,10 @@ int storeLogMsg(const char *fmt, ...)
     memset(Buf,0,sizeof(Buf));
     CurrentTime = time(NULL);
     tm=localtime(&CurrentTime);
-    sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d] - %s\" >> /Storage/SystemLog/[%04d.%02d]Upgrade_SystemLog",
-            tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,
+    gettimeofday(&tv, NULL); // get microseconds, 10^-6
+
+    sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d.%06ld]%s\" >> /Storage/SystemLog/[%04d.%02d]Module_Upgrade",
+            tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec,
             buffer,
             tm->tm_year+1900,tm->tm_mon+1);
 
@@ -49,7 +52,7 @@ int storeLogMsg(const char *fmt, ...)
 #endif
 
 #ifdef ConsloePrintLog
-    printf("[%04d.%02d.%02d %02d:%02d:%02d] - %s", tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec, buffer);
+    printf("[%04d.%02d.%02d %02d:%02d:%02d.%06ld]%s", tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec, buffer);
 #endif
 
     return rc;

EVSE/Modularization/ocppfiles/SystemLogMessage.c

@@ -8,6 +8,7 @@ int StoreLogMsg(const char *fmt, ...)
 	//char buffer[4096];
 	time_t CurrentTime;
 	struct tm *tm;
+	struct timeval tv;
 	va_list args;
 
 	va_start(args, fmt);
@@ -16,16 +17,16 @@ int StoreLogMsg(const char *fmt, ...)
 	memset(Buf,0,sizeof(Buf));
 	CurrentTime = time(NULL);
 	tm=localtime(&CurrentTime);
-	sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d] - %s\" >>  /Storage/OCPP/[%04d.%02d]SystemLog",
-			tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,
+	gettimeofday(&tv, NULL); // get microseconds, 10^-6
+
+	sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d.%06ld]%s\" >>  /Storage/OCPP/[%04d.%02d]SystemLog",
+			tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec,
 			buffer,
 			tm->tm_year+1900,tm->tm_mon+1);
-	//printf("buffer: %s\n",Buf );
-	//execl("sh", "sh", "-c", Buf, NULL);//system((const char*)Buf);
 	system((const char*)Buf);
 
 #ifdef ConsloePrintLog
-	printf("[%04d.%02d.%02d %02d:%02d:%02d] - %s", tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec, buffer);
+	printf("[%04d.%02d.%02d %02d:%02d:%02d.%06ld]%s", tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec, buffer);
 #endif
 
 	return rc;
@@ -39,6 +40,7 @@ int StoreOcppMsg(const char *fmt, ...)
 	//char buffer[4096];
 	time_t CurrentTime;
 	struct tm *tm;
+	struct timeval tv;
 	va_list args;
 
 	va_start(args, fmt);
@@ -47,16 +49,16 @@ int StoreOcppMsg(const char *fmt, ...)
 	memset(Buf,0,sizeof(Buf));
 	CurrentTime = time(NULL);
 	tm=localtime(&CurrentTime);
-	sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d] - %s\" >>  /Storage/OCPP/[%04d.%02d]OcppMessage",
-			tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,
+	gettimeofday(&tv, NULL); // get microseconds, 10^-6
+
+	sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d.%06ld]%s\" >>  /Storage/OCPP/[%04d.%02d]OcppMessage",
+			tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec,
 			buffer,
 			tm->tm_year+1900,tm->tm_mon+1);
-	//printf("buffer: %s\n",Buf );
-	//execl("sh", "sh", "-c", Buf, NULL);//system((const char*)Buf);
 	system((const char*)Buf);
 
 #ifdef ConsloePrintLog
-	printf("[%04d.%02d.%02d %02d:%02d:%02d] - %s", tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec, buffer);
+	printf("[%04d.%02d.%02d %02d:%02d:%02d.%06ld]%s", tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec, buffer);
 #endif
 	return rc;
 }

EVSE/Projects/AW-CCS/Apps/LCM/Module_LcmControl.c

@@ -75,7 +75,7 @@ int StoreLogMsg(const char *fmt, ...)
 	tm=localtime(&CurrentTime);
 	gettimeofday(&tv, NULL); // get microseconds, 10^-6
 
-	sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d.%06ld] - %s\" >> /Storage/SystemLog/[%04d.%02d]Module_LcmControl",
+	sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d.%06ld]%s\" >> /Storage/SystemLog/[%04d.%02d]Module_LcmControl",
 						tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec,
 						buffer,
 						tm->tm_year+1900,tm->tm_mon+1);
@@ -85,7 +85,7 @@ int StoreLogMsg(const char *fmt, ...)
 #endif
 
 #ifdef ConsloePrintLog
-	printf("[%04d.%02d.%02d %02d:%02d:%02d.%06ld] - %s", tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec, buffer);
+	printf("[%04d.%02d.%02d %02d:%02d:%02d.%06ld]%s", tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec, buffer);
 #endif
 
 	return rc;
@@ -822,7 +822,7 @@ int InitComPort()
 	tios.c_iflag = 0;
 	tios.c_oflag = 0;
 	tios.c_cc[VMIN]=0;
-	tios.c_cc[VTIME]=(unsigned char)1;		// timeout 0.5 secod
+	tios.c_cc[VTIME]=(unsigned char)5;		// timeout 500ms
 	tios.c_lflag=0;
 	tcflush(fd, TCIFLUSH);
 	ioctl (fd, TCSETS, &tios);

EVSE/Projects/AW-CCS/Apps/Module_AlarmDetect.c

@@ -80,6 +80,7 @@ int StoreLogMsg(const char *fmt, ...)
 	char buffer[4096];
 	time_t CurrentTime;
 	struct tm *tm;
+	struct timeval tv;
 	va_list args;
 
 	va_start(args, fmt);
@@ -89,11 +90,12 @@ int StoreLogMsg(const char *fmt, ...)
 	memset(Buf,0,sizeof(Buf));
 	CurrentTime = time(NULL);
 	tm=localtime(&CurrentTime);
+	gettimeofday(&tv, NULL); // get microseconds, 10^-6
 
 	if((ShmSysConfigAndInfo->SysConfig.ModelName != NULL) && (ShmSysConfigAndInfo->SysConfig.SerialNumber != NULL) && (strlen((char*)ShmSysConfigAndInfo->SysConfig.ModelName) >= 14))
 	{
-		sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d] - %s\" >> /Storage/SystemLog/[%04d.%02d]%s_%s_SystemLog",
-					tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,
+		sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d.%06ld]%s\" >> /Storage/SystemLog/[%04d.%02d]%s_%s_SystemLog",
+					tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec,
 					buffer,
 					tm->tm_year+1900,tm->tm_mon+1,
 					ShmSysConfigAndInfo->SysConfig.ModelName,
@@ -101,8 +103,8 @@ int StoreLogMsg(const char *fmt, ...)
 	}
 	else
 	{
-		sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d] - %s\" >> /Storage/SystemLog/[%04d.%02d]SystemLog",
-					tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,
+		sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d.%06ld]%s\" >> /Storage/SystemLog/[%04d.%02d]SystemLog",
+					tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec,
 					buffer,
 					tm->tm_year+1900,tm->tm_mon+1);
 	}
@@ -112,7 +114,7 @@ int StoreLogMsg(const char *fmt, ...)
 #endif
 
 #ifdef ConsloePrintLog
-	printf("[%04d.%02d.%02d %02d:%02d:%02d] - %s", tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec, buffer);
+	printf("[%04d.%02d.%02d %02d:%02d:%02d.%06ld]%s", tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec, buffer);
 #endif
 
 	return rc;

EVSE/Projects/AW-CCS/Apps/Module_ConfigTools.c

@@ -63,6 +63,7 @@ int StoreLogMsg(const char *fmt, ...)
 	char buffer[4096];
 	time_t CurrentTime;
 	struct tm *tm;
+	struct timeval tv;
 	va_list args;
 
 	va_start(args, fmt);
@@ -72,9 +73,10 @@ int StoreLogMsg(const char *fmt, ...)
 	memset(Buf,0,sizeof(Buf));
 	CurrentTime = time(NULL);
 	tm=localtime(&CurrentTime);
+	gettimeofday(&tv, NULL); // get microseconds, 10^-6
 
-	sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d] - %s\" >> /Storage/SystemLog/[%04d.%02d]ConfigToolsLog",
-				tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,
+	sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d.%06ld]%s\" >> /Storage/SystemLog/[%04d.%02d]ConfigToolsLog",
+				tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec,
 				buffer,
 				tm->tm_year+1900,tm->tm_mon+1);
 
@@ -84,7 +86,7 @@ int StoreLogMsg(const char *fmt, ...)
 #endif
 
 #ifdef ConsloePrintLog
-	printf("[%04d.%02d.%02d %02d:%02d:%02d] - %s", tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec, buffer);
+	printf("[%04d.%02d.%02d %02d:%02d:%02d.%06ld]%s", tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec, buffer);
 #endif
 
 	return rc;

EVSE/Projects/AW-CCS/Apps/Module_Debug.c

@@ -48,6 +48,7 @@ int StoreLogMsg(const char *fmt, ...)
 	char buffer[4096];
 	time_t CurrentTime;
 	struct tm *tm;
+	struct timeval tv;
 	va_list args;
 
 	va_start(args, fmt);
@@ -57,30 +58,19 @@ int StoreLogMsg(const char *fmt, ...)
 	memset(Buf,0,sizeof(Buf));
 	CurrentTime = time(NULL);
 	tm=localtime(&CurrentTime);
+	gettimeofday(&tv, NULL); // get microseconds, 10^-6
 
-	if((ShmSysConfigAndInfo->SysConfig.ModelName != NULL) && (ShmSysConfigAndInfo->SysConfig.SerialNumber != NULL) && (strlen((char*)ShmSysConfigAndInfo->SysConfig.ModelName) >= 14))
-	{
-		sprintf(Buf,"echo \"[%04d.%02d.%02d %02d:%02d:%02d] - %s\" >> /Storage/SystemLog/[%04d.%02d]%s_%s_SystemLog",
-					tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,
-					buffer,
-					tm->tm_year+1900,tm->tm_mon+1,
-					ShmSysConfigAndInfo->SysConfig.ModelName,
-					ShmSysConfigAndInfo->SysConfig.SerialNumber);
-	}
-	else
-	{
-		sprintf(Buf,"echo \"[%04d.%02d.%02d %02d:%02d:%02d] - %s\" >> /Storage/SystemLog/[%04d.%02d]SystemLog",
-					tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,
-					buffer,
-					tm->tm_year+1900,tm->tm_mon+1);
-	}
+	sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d.%06ld]%s\" >> /Storage/SystemLog/[%04d.%02d]Module_Debug",
+				tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec,
+				buffer,
+				tm->tm_year+1900,tm->tm_mon+1);
 
 #ifdef SystemLogMessage
 	system(Buf);
 #endif
 
 #ifdef ConsloePrintLog
-	printf("[%04d.%02d.%02d %02d:%02d:%02d] - %s", tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec, buffer);
+	printf("[%04d.%02d.%02d %02d:%02d:%02d.%06ld]%s", tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec, buffer);
 #endif
 
 	return rc;

EVSE/Projects/AW-CCS/Apps/Module_EventLogging.c

@@ -55,6 +55,7 @@ int StoreLogMsg(const char *fmt, ...)
 	char buffer[4096];
 	time_t CurrentTime;
 	struct tm *tm;
+	struct timeval tv;
 	va_list args;
 
 	va_start(args, fmt);
@@ -64,15 +65,17 @@ int StoreLogMsg(const char *fmt, ...)
 	memset(Buf,0,sizeof(Buf));
 	CurrentTime = time(NULL);
 	tm=localtime(&CurrentTime);
-	sprintf(Buf,"echo \"[%04d.%02d.%02d %02d:%02d:%02d] - %s\" >> /Storage/Eventlog/[%04d.%02d]EventLog",
-			tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,
+	gettimeofday(&tv, NULL); // get microseconds, 10^-6
+		
+	sprintf(Buf,"echo \"[%04d.%02d.%02d %02d:%02d:%02d.%06ld]%s\" >> /Storage/Eventlog/[%04d.%02d]EventLog",
+			tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec,
 			buffer,
 			tm->tm_year+1900,tm->tm_mon+1);
 #ifdef SystemLogMessage
 	system(Buf);
 #endif
 
-	printf("[%04d.%02d.%02d %02d:%02d:%02d] - %s", tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec, buffer);
+	printf("[%04d.%02d.%02d %02d:%02d:%02d.%06ld]%s", tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec, buffer);
 
 	return rc;
 }
@@ -84,6 +87,7 @@ int StoreEventLogMsg(const char *fmt, ...)
 	char buffer[4096];
 	time_t CurrentTime;
 	struct tm *tm;
+	struct timeval tv;
 	va_list args;
 
 	va_start(args, fmt);
@@ -93,11 +97,12 @@ int StoreEventLogMsg(const char *fmt, ...)
 	memset(Buf,0,sizeof(Buf));
 	CurrentTime = time(NULL);
 	tm=localtime(&CurrentTime);
+	gettimeofday(&tv, NULL); // get microseconds, 10^-6
 
 	if((ShmSysConfigAndInfo->SysConfig.ModelName != NULL) && (ShmSysConfigAndInfo->SysConfig.SerialNumber != NULL) && (strlen((char*)ShmSysConfigAndInfo->SysConfig.ModelName) >= 14))
 	{
-		sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d] - %s\" >> /Storage/EventLog/[%04d.%02d]%s_%s_EventLog",
-					tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,
+		sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d.%06ld]%s\" >> /Storage/EventLog/[%04d.%02d]%s_%s_EventLog",
+					tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec,
 					buffer,
 					tm->tm_year+1900,tm->tm_mon+1,
 					ShmSysConfigAndInfo->SysConfig.ModelName,
@@ -105,8 +110,8 @@ int StoreEventLogMsg(const char *fmt, ...)
 	}
 	else
 	{
-		sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d] - %s\" >> /Storage/EventLog/[%04d.%02d]EventLog",
-					tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,
+		sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d.%06ld]%s\" >> /Storage/EventLog/[%04d.%02d]EventLog",
+					tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec,
 					buffer,
 					tm->tm_year+1900,tm->tm_mon+1);
 	}
@@ -116,7 +121,7 @@ int StoreEventLogMsg(const char *fmt, ...)
 #endif
 
 #ifdef ConsloePrintLog
-	printf("[%04d.%02d.%02d %02d:%02d:%02d] - %s", tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec, buffer);
+	printf("[%04d.%02d.%02d %02d:%02d:%02d.%06ld]%s", tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec, buffer);
 #endif
 
 	return rc;

EVSE/Projects/AW-CCS/Apps/Module_FactoryConfig.c

@@ -57,6 +57,7 @@ int StoreLogMsg(const char *fmt, ...)
 	char buffer[4096];
 	time_t CurrentTime;
 	struct tm *tm;
+	struct timeval tv;
 	va_list args;
 
 	va_start(args, fmt);
@@ -66,17 +67,32 @@ int StoreLogMsg(const char *fmt, ...)
 	memset(Buf,0,sizeof(Buf));
 	CurrentTime = time(NULL);
 	tm=localtime(&CurrentTime);
-	sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d] - %s\" >> /Storage/SystemLog/%04d-%02d_%s_%s_SystemLog",
-			tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,
-			buffer,
-			tm->tm_year+1900,tm->tm_mon+1,
-			SysConfig.ModelName,
-			SysConfig.SerialNumber);
+	gettimeofday(&tv, NULL); // get microseconds, 10^-6
+
+	if((ShmSysConfigAndInfo->SysConfig.ModelName != NULL) && (ShmSysConfigAndInfo->SysConfig.SerialNumber != NULL) && (strlen((char*)ShmSysConfigAndInfo->SysConfig.ModelName) >= 14))
+	{
+		sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d.%06ld]-%s\" >> /Storage/SystemLog/[%04d.%02d]%s_%s_SystemLog",
+					tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec,
+					buffer,
+					tm->tm_year+1900,tm->tm_mon+1,
+					ShmSysConfigAndInfo->SysConfig.ModelName,
+					ShmSysConfigAndInfo->SysConfig.SerialNumber);
+	}
+	else
+	{
+		sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d.%06ld]-%s\" >> /Storage/SystemLog/[%04d.%02d]SystemLog",
+					tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec,
+					buffer,
+					tm->tm_year+1900,tm->tm_mon+1);
+	}
+
 #ifdef SystemLogMessage
 	system(Buf);
 #endif
 
-	printf("[%04d.%02d.%02d %02d:%02d:%02d] - %s", tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec, buffer);
+#ifdef ConsloePrintLog
+	printf("[%04d.%02d.%02d %02d:%02d:%02d.%06ld] - %s", tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec, buffer);
+#endif
 
 	return rc;
 }

EVSE/Projects/AW-CCS/Apps/Module_InternalComm.c

@@ -65,6 +65,7 @@ int StoreLogMsg(const char *fmt, ...)
 	char buffer[4096];
 	time_t CurrentTime;
 	struct tm *tm;
+	struct timeval tv;
 	va_list args;
 
 	va_start(args, fmt);
@@ -74,9 +75,10 @@ int StoreLogMsg(const char *fmt, ...)
 	memset(Buf,0,sizeof(Buf));
 	CurrentTime = time(NULL);
 	tm=localtime(&CurrentTime);
+	gettimeofday(&tv, NULL); // get microseconds, 10^-6
 
-	sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d] - %s\" >> /Storage/SystemLog/[%04d.%02d]Module_InterComm",
-				tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,
+	sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d.%06ld]%s\" >> /Storage/SystemLog/[%04d.%02d]Module_InterComm",
+				tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec,
 				buffer,
 				tm->tm_year+1900,tm->tm_mon+1);
 
@@ -85,7 +87,7 @@ int StoreLogMsg(const char *fmt, ...)
 #endif
 
 #ifdef ConsloePrintLog
-	printf("[%04d.%02d.%02d %02d:%02d:%02d] - %s", tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec, buffer);
+	printf("[%04d.%02d.%02d %02d:%02d:%02d.%06ld]%s", tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec, buffer);
 #endif
 
 	return rc;
@@ -2158,9 +2160,9 @@ int main(void)
 					{
 						if(Config_AC_MCU_RESET_REQUEST(Uart1Fd, (gun_index>0?ADDR_AC_PRIMARY_2:ADDR_AC_PRIMARY_1), &ShmCharger->gun_info[gun_index].mcuResetRequest) == PASS)
 						{
-							DEBUG_INFO("**************************************************\n");
-							DEBUG_INFO("********* High priority polling : Case 7 *********\n");
-							DEBUG_INFO("**************************************************\n");
+							DEBUG_INFO("*******************************************\n");
+							DEBUG_INFO("**** High priority polling : Case 7 *******\n");
+							DEBUG_INFO("*******************************************\n");
 							DEBUG_INFO("MCU-%d set MCU reset Request : %d\n", gun_index, ShmCharger->gun_info[gun_index].mcuResetRequest.isMcuResetRequest);
 
 							ShmCharger->gun_info[gun_index].mcuResetRequest.isMcuResetRequest = OFF;
@@ -2208,26 +2210,26 @@ int main(void)
 					//===============================
 					// Config primary MCU LED
 					//===============================
-					DEBUG_INFO("**************************************************\n");
-					DEBUG_INFO("********* High priority polling : Case 1 *********\n");
-					DEBUG_INFO("**************************************************\n");
+					DEBUG_INFO("*******************************************\n");
+					DEBUG_INFO("***** High priority polling : Case 1 ******\n");
+					DEBUG_INFO("*******************************************\n");
 					DEBUG_INFO("MCU-%d set Led mode : %d\n",gun_index, ShmCharger->gun_info[gun_index].primaryMcuLed.mode);
 					DEBUG_INFO("MCU-%d set Alarm code : %x\n",gun_index, ShmCharger->gun_info[gun_index].primaryMcuLed.alarm_code);
 
 					//===============================
 					// Config primary Legacy request
 					//===============================
-					DEBUG_INFO("**************************************************\n");
-					DEBUG_INFO("********* High priority polling : Case 2 *********\n");
-					DEBUG_INFO("**************************************************\n");
+					DEBUG_INFO("*******************************************\n");
+					DEBUG_INFO("***** High priority polling : Case 2 ******\n");
+					DEBUG_INFO("*******************************************\n");
 					DEBUG_INFO("MCU-%d set relay request : %d\n", gun_index, ShmCharger->gun_info[gun_index].legacyRequest.isLegacyRequest);
 
 					//===============================
 					// Query primary MCU status
 					//===============================
-					DEBUG_INFO("**************************************************\n");
-					DEBUG_INFO("********* High priority polling : Case 3 *********\n");
-					DEBUG_INFO("**************************************************\n");
+					DEBUG_INFO("*******************************************\n");
+					DEBUG_INFO("***** High priority polling : Case 3 ******\n");
+					DEBUG_INFO("*******************************************\n");
 					DEBUG_INFO("MCU-%d get Pilot State : %d\n", gun_index, ShmCharger->gun_info[gun_index].primaryMcuState.cp_state);
 					DEBUG_INFO("MCU-%d get Pilot Duty : %.2f\n", gun_index, (float)ShmCharger->gun_info[gun_index].primaryMcuState.current_limit);
 					DEBUG_INFO("MCU-%d get Pilot Voltage Positive : %.2f\n", gun_index, ShmCharger->gun_info[gun_index].primaryMcuState.cp_voltage_positive);
@@ -2248,9 +2250,9 @@ int main(void)
 					//===============================
 					if((ShmCharger->gun_info[gun_index].primaryMcuAlarm.InputAlarmCode>0))
 					{
-						DEBUG_INFO("**************************************************\n");
-						DEBUG_INFO("********* High priority polling : Case 4 *********\n");
-						DEBUG_INFO("**************************************************\n");
+						DEBUG_INFO("*******************************************\n");
+						DEBUG_INFO("***** High priority polling : Case 4 ******\n");
+						DEBUG_INFO("*******************************************\n");
 						DEBUG_INFO("MCU-%d get OVP_L1 : %d\n", gun_index, ShmCharger->gun_info[gun_index].primaryMcuAlarm.bits.OVP_L1);
 						DEBUG_INFO("MCU-%d get UVP_L1 : %d\n", gun_index, ShmCharger->gun_info[gun_index].primaryMcuAlarm.bits.UVP_L1);
 						DEBUG_INFO("MCU-%d get OCP_L1 : %d\n", gun_index, ShmCharger->gun_info[gun_index].primaryMcuAlarm.bits.OCP_L1);
@@ -2292,9 +2294,9 @@ int main(void)
 					//===============================
 					if(ShmCharger->gun_info[gun_index].bleConfigData.isLogin == ON)
 					{
-						DEBUG_INFO("**************************************************\n");
-						DEBUG_INFO("********* High priority polling : Case 5 *********\n");
-						DEBUG_INFO("**************************************************\n");
+						DEBUG_INFO("*******************************************\n");
+						DEBUG_INFO("***** High priority polling : Case 5 ******\n");
+						DEBUG_INFO("*******************************************\n");
 						DEBUG_INFO("MCU-%d get isUserLogin : %d\n", gun_index, ShmCharger->gun_info[gun_index].bleConfigData.isLogin);
 						DEBUG_INFO("MCU-%d get isRequestStartCharger : %d\n", gun_index, ShmCharger->gun_info[gun_index].bleConfigData.isRequestStart);
 						DEBUG_INFO("MCU-%d get isRequestStopCharger : %d\n", gun_index, ShmCharger->gun_info[gun_index].bleConfigData.isRequestStop);
@@ -2305,9 +2307,9 @@ int main(void)
 					//===============================
 					if(strcmp((char *)&ShmCharger->gun_info[gun_index].bleLoginCentralId.id,"") != 0)
 					{
-						DEBUG_INFO("**************************************************\n");
-						DEBUG_INFO("********* High priority polling : Case 6 *********\n");
-						DEBUG_INFO("**************************************************\n");
+						DEBUG_INFO("*******************************************\n");
+						DEBUG_INFO("***** High priority polling : Case 6 ******\n");
+						DEBUG_INFO("*******************************************\n");
 						DEBUG_INFO("MCU-%d get ble central id : %s\n", gun_index, ShmCharger->gun_info[gun_index].bleLoginCentralId.id);
 					}
 				}
@@ -2503,9 +2505,9 @@ int main(void)
 						//===============================
 						if(ShmCharger->gun_info[gun_index].mcuFlag.isMcuUpgradeReq)
 						{
-							DEBUG_INFO("==================================================\n");
-							DEBUG_INFO("======== Normal priority polling : Case 15 =======\n");
-							DEBUG_INFO("==================================================\n");
+							DEBUG_INFO("===========================================\n");
+							DEBUG_INFO("==== Normal priority polling : Case 15 ====\n");
+							DEBUG_INFO("===========================================\n");
 
 							unsigned char cmd[512];
 							if(Upgrade_UART(Uart1Fd, AC_WALLMOUNT_CONTROLLER, (gun_index>0?ADDR_AC_PRIMARY_2:ADDR_AC_PRIMARY_1), ShmCharger->fwUpgradeInfo.location, ShmCharger->fwUpgradeInfo.modelName))
@@ -2574,9 +2576,9 @@ int main(void)
 						//===============================
 						if(ShmCharger->gun_info[gun_index].mcuFlag.isReadFwVerPass != PASS)
 						{
-							DEBUG_INFO("==================================================\n");
-							DEBUG_INFO("======== Normal priority polling : Case 21-1======\n");
-							DEBUG_INFO("==================================================\n");
+							DEBUG_INFO("===========================================\n");
+							DEBUG_INFO("==== Normal priority polling : Case 21-1===\n");
+							DEBUG_INFO("===========================================\n");
 							if(Query_FW_Ver(Uart1Fd, (gun_index>0?ADDR_AC_PRIMARY_2:ADDR_AC_PRIMARY_1), &ShmCharger->gun_info[gun_index].ver) == PASS)
 							{
 								DEBUG_INFO("MCU-%d get firmware version : %s\n", gun_index, ShmCharger->gun_info[gun_index].ver.Version_FW);
@@ -2600,9 +2602,9 @@ int main(void)
 						//===============================
 						if(ShmCharger->gun_info[gun_index].mcuFlag.isSetSerialNumberPass != PASS)
 						{
-							DEBUG_INFO("==================================================\n");
-							DEBUG_INFO("======== Normal priority polling : Case 21-2======\n");
-							DEBUG_INFO("==================================================\n");
+							DEBUG_INFO("===========================================\n");
+							DEBUG_INFO("==== Normal priority polling : Case 21-2===\n");
+							DEBUG_INFO("===========================================\n");
 							memcpy(ShmCharger->evseId.serial_number, ShmSysConfigAndInfo->SysConfig.SerialNumber, ARRAY_SIZE(ShmCharger->evseId.serial_number));
 							if(Config_Serial_Number(Uart1Fd, (gun_index>0?ADDR_AC_PRIMARY_2:ADDR_AC_PRIMARY_1), &ShmCharger->evseId))
 							{
@@ -2626,9 +2628,9 @@ int main(void)
 						//===============================
 						if(ShmCharger->gun_info[gun_index].mcuFlag.isSetModelNamePass != PASS)
 						{
-							DEBUG_INFO("==================================================\n");
-							DEBUG_INFO("======== Normal priority polling : Case 21-3======\n");
-							DEBUG_INFO("==================================================\n");
+							DEBUG_INFO("===========================================\n");
+							DEBUG_INFO("==== Normal priority polling : Case 21-3===\n");
+							DEBUG_INFO("===========================================\n");
 							memcpy(ShmCharger->evseId.model_name, ShmSysConfigAndInfo->SysConfig.ModelName, ARRAY_SIZE(ShmCharger->evseId.model_name));
 							if(Config_Model_Name(Uart1Fd, (gun_index>0?ADDR_AC_PRIMARY_2:ADDR_AC_PRIMARY_1), &ShmCharger->evseId))
 							{
@@ -2662,9 +2664,9 @@ int main(void)
 					switch(logIndex)
 					{
 						case 1:
-							DEBUG_INFO("==================================================\n");
-							DEBUG_INFO("======== Normal priority polling : Case 3 ========\n");
-							DEBUG_INFO("==================================================\n");
+							DEBUG_INFO("===========================================\n");
+							DEBUG_INFO("==== Normal priority polling : Case 3 =====\n");
+							DEBUG_INFO("===========================================\n");
 							DEBUG_INFO("MCU-%d get output current L1: %f\n", gun_index, (float)ShmCharger->gun_info[gun_index].outputCurrent.L1N_L12[0]);
 							if(ShmSysConfigAndInfo->SysConfig.AcPhaseCount == 3)
 							{
@@ -2673,27 +2675,27 @@ int main(void)
 							}
 							break;
 						case 2:
-							DEBUG_INFO("==================================================\n");
-							DEBUG_INFO("======== Normal priority polling : Case 5 ========\n");
-							DEBUG_INFO("==================================================\n");
+							DEBUG_INFO("===========================================\n");
+							DEBUG_INFO("==== Normal priority polling : Case 5 =====\n");
+							DEBUG_INFO("===========================================\n");
 							DEBUG_INFO("MCU-%d get gun plugin times : %ld\n", gun_index, (long)ShmCharger->gun_info[gun_index].gunPluginTimes.GunPluginTimes);
 							break;
 						case 3:
-							DEBUG_INFO("==================================================\n");
-							DEBUG_INFO("======== Normal priority polling : Case 7 ========\n");
-							DEBUG_INFO("==================================================\n");
+							DEBUG_INFO("===========================================\n");
+							DEBUG_INFO("==== Normal priority polling : Case 7 =====\n");
+							DEBUG_INFO("===========================================\n");
 							DEBUG_INFO("MCU-%d get temperature : %d\n", gun_index, ShmCharger->gun_info[gun_index].temperature.point[0]);
 							break;
 						case 4:
-							DEBUG_INFO("==================================================\n");
-							DEBUG_INFO("======== Normal priority polling : Case 9 ========\n");
-							DEBUG_INFO("==================================================\n");
+							DEBUG_INFO("===========================================\n");
+							DEBUG_INFO("==== Normal priority polling : Case 9 =====\n");
+							DEBUG_INFO("===========================================\n");
 							DEBUG_INFO("MCU-%d set cp pwn duty : %d\n",gun_index, ShmCharger->gun_info[gun_index].primaryMcuCp_Pwn_Duty.max_current);
 							break;
 						case 5:
-							DEBUG_INFO("==================================================\n");
-							DEBUG_INFO("======== Normal priority polling : Case 11 =======\n");
-							DEBUG_INFO("==================================================\n");
+							DEBUG_INFO("===========================================\n");
+							DEBUG_INFO("==== Normal priority polling : Case 11 ====\n");
+							DEBUG_INFO("===========================================\n");
 							if(ShmCharger->gun_info[gun_index].bleConfigData.isLogin && !ShmOCPP16Data->OcppConnStatus)
 							{
 								DEBUG_INFO("Sync from MCU-%d rtc OK...%04d-%02d-%02d %02d:%02d:%02d\n", gun_index,
@@ -2718,9 +2720,9 @@ int main(void)
 							}
 							break;
 						case 6:
-							DEBUG_INFO("==================================================\n");
-							DEBUG_INFO("======== Normal priority polling : Case 13 =======\n");
-							DEBUG_INFO("==================================================\n");
+							DEBUG_INFO("===========================================\n");
+							DEBUG_INFO("==== Normal priority polling : Case 13 ====\n");
+							DEBUG_INFO("===========================================\n");
 							DEBUG_INFO("MCU-%d get total power consumption : %f kWh\n",gun_index, ((float)ShmCharger->gun_info[gun_index].powerConsumptionTotal.power_consumption/100));
 							DEBUG_INFO("MCU-%d get L1N_L12 power consumption : %f kWh\n",gun_index, ((float)ShmCharger->gun_info[gun_index].powerConsumption[0].power_consumption/100));
 							if(ShmSysConfigAndInfo->SysConfig.AcPhaseCount == 3)
@@ -2732,9 +2734,9 @@ int main(void)
 						case 7:
 							if(ShmCharger->gun_info[gun_index].isSetBreatheLedTiming == ON)
 							{
-								DEBUG_INFO("==================================================\n");
-								DEBUG_INFO("======== Normal priority polling : Case 17 =======\n");
-								DEBUG_INFO("==================================================\n");
+								DEBUG_INFO("===========================================\n");
+								DEBUG_INFO("==== Normal priority polling : Case 17 ====\n");
+								DEBUG_INFO("===========================================\n");
 								DEBUG_INFO("MCU-%d set breathe led timing : Authed Fade in [%ld].\n", gun_index, (long)ShmCharger->gun_info[gun_index].setBreatheLedTiming.set_Led_Action_Authed_Fade_In);
 								DEBUG_INFO("MCU-%d set breathe led timing : Authed Fade out [%ld].\n", gun_index, (long)ShmCharger->gun_info[gun_index].setBreatheLedTiming.set_Led_Action_Authed_Fade_Out);
 								DEBUG_INFO("MCU-%d set breathe led timing : Charging Fade in [%ld].\n", gun_index, (long)ShmCharger->gun_info[gun_index].setBreatheLedTiming.Set_Led_Action_Chaging_Fade_In);
@@ -2746,9 +2748,9 @@ int main(void)
 						case 8:
 							if(ShmCharger->gun_info[gun_index].isSetLedBrightness == ON)
 							{
-								DEBUG_INFO("==================================================\n");
-								DEBUG_INFO("======== Normal priority polling : Case 19 =======\n");
-								DEBUG_INFO("==================================================\n");
+								DEBUG_INFO("===========================================\n");
+								DEBUG_INFO("==== Normal priority polling : Case 19 ====\n");
+								DEBUG_INFO("===========================================\n");
 								DEBUG_INFO("MCU-%d set led brightness Sector 01 : [%x].\n", gun_index, ShmCharger->gun_info[gun_index].setLedBrightness.sector_1);
 								DEBUG_INFO("MCU-%d set led brightness Sector 02 : [%x].\n", gun_index, ShmCharger->gun_info[gun_index].setLedBrightness.sector_2);
 								DEBUG_INFO("MCU-%d set led brightness Sector 03 : [%x].\n", gun_index, ShmCharger->gun_info[gun_index].setLedBrightness.sector_3);
@@ -2764,9 +2766,9 @@ int main(void)
 							}
 							break;
 						default:
-							DEBUG_INFO("==================================================\n");
-							DEBUG_INFO("======== Normal priority polling : Case 1 ========\n");
-							DEBUG_INFO("==================================================\n");
+							DEBUG_INFO("===========================================\n");
+							DEBUG_INFO("==== Normal priority polling : Case 1 =====\n");
+							DEBUG_INFO("===========================================\n");
 							DEBUG_INFO("MCU-%d get input voltage L1: %f\n", gun_index, (float)ShmCharger->gun_info[gun_index].inputVoltage.L1N_L12);
 							DEBUG_INFO("MCU-%d get PresentChargingVoltage L1: %.2f\n", gun_index, (float)ShmSysConfigAndInfo->SysInfo.AcChargingData[gun_index].PresentChargingVoltage);
 

EVSE/Projects/AW-CCS/Apps/Module_Speaker.c

@@ -70,6 +70,7 @@ int StoreLogMsg(const char *fmt, ...)
 	char buffer[4096];
 	time_t CurrentTime;
 	struct tm *tm;
+	struct timeval tv;
 	va_list args;
 
 	va_start(args, fmt);
@@ -79,11 +80,12 @@ int StoreLogMsg(const char *fmt, ...)
 	memset(Buf,0,sizeof(Buf));
 	CurrentTime = time(NULL);
 	tm=localtime(&CurrentTime);
+	gettimeofday(&tv, NULL); // get microseconds, 10^-6
 
 	if((ShmSysConfigAndInfo->SysConfig.ModelName != NULL) && (ShmSysConfigAndInfo->SysConfig.SerialNumber != NULL) && (strlen((char*)ShmSysConfigAndInfo->SysConfig.ModelName) >= 14))
 	{
-		sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d] - %s\" >> /Storage/SystemLog/[%04d.%02d]%s_%s_SystemLog",
-					tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,
+		sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d.%06ld]%s\" >> /Storage/SystemLog/[%04d.%02d]%s_%s_SystemLog",
+					tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec,
 					buffer,
 					tm->tm_year+1900,tm->tm_mon+1,
 					ShmSysConfigAndInfo->SysConfig.ModelName,
@@ -91,8 +93,8 @@ int StoreLogMsg(const char *fmt, ...)
 	}
 	else
 	{
-		sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d] - %s\" >> /Storage/SystemLog/[%04d.%02d]SystemLog",
-					tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,
+		sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d.%06ld]%s\" >> /Storage/SystemLog/[%04d.%02d]SystemLog",
+					tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec,
 					buffer,
 					tm->tm_year+1900,tm->tm_mon+1);
 	}
@@ -102,7 +104,7 @@ int StoreLogMsg(const char *fmt, ...)
 #endif
 
 #ifdef ConsloePrintLog
-	printf("[%04d.%02d.%02d %02d:%02d:%02d] - %s", tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec, buffer);
+	printf("[%04d.%02d.%02d %02d:%02d:%02d.%06ld]%s", tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec, buffer);
 #endif
 
 	return rc;

EVSE/Projects/AW-CCS/Apps/main.c

@@ -150,6 +150,7 @@ int StoreLogMsg(const char *fmt, ...)
 	char buffer[4096];
 	time_t CurrentTime;
 	struct tm *tm;
+	struct timeval tv;
 	va_list args;
 
 	va_start(args, fmt);
@@ -159,11 +160,12 @@ int StoreLogMsg(const char *fmt, ...)
 	memset(Buf,0,sizeof(Buf));
 	CurrentTime = time(NULL);
 	tm=localtime(&CurrentTime);
+	gettimeofday(&tv, NULL); // get microseconds, 10^-6
 
 	if((ShmSysConfigAndInfo->SysConfig.ModelName != NULL) && (ShmSysConfigAndInfo->SysConfig.SerialNumber != NULL) && (strlen((char*)ShmSysConfigAndInfo->SysConfig.ModelName) >= 14))
 	{
-		sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d] - %s\" >> /Storage/SystemLog/[%04d.%02d]%s_%s_SystemLog",
-					tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,
+		sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d.%06ld]%s\" >> /Storage/SystemLog/[%04d.%02d]%s_%s_SystemLog",
+					tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec,
 					buffer,
 					tm->tm_year+1900,tm->tm_mon+1,
 					ShmSysConfigAndInfo->SysConfig.ModelName,
@@ -171,8 +173,8 @@ int StoreLogMsg(const char *fmt, ...)
 	}
 	else
 	{
-		sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d] - %s\" >> /Storage/SystemLog/[%04d.%02d]SystemLog",
-					tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,
+		sprintf(Buf,"echo -n \"[%04d.%02d.%02d %02d:%02d:%02d.%06ld]%s\" >> /Storage/SystemLog/[%04d.%02d]SystemLog",
+					tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec,
 					buffer,
 					tm->tm_year+1900,tm->tm_mon+1);
 	}
@@ -182,7 +184,7 @@ int StoreLogMsg(const char *fmt, ...)
 #endif
 
 #ifdef ConsloePrintLog
-	printf("[%04d.%02d.%02d %02d:%02d:%02d] - %s", tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec, buffer);
+	printf("[%04d.%02d.%02d %02d:%02d:%02d.%06ld]%s", tm->tm_year+1900,tm->tm_mon+1,tm->tm_mday,tm->tm_hour,tm->tm_min,tm->tm_sec,tv.tv_usec, buffer);
 #endif
 
 	return rc;
@@ -1359,7 +1361,7 @@ void get_firmware_version(unsigned char gun_index)
 	strcpy((char*)ShmSysConfigAndInfo->SysInfo.CsuPrimFwRev, ShmCharger->gun_info[gun_index].ver.Version_FW);
 
 	// Get CSU root file system version
-	sprintf((char*)ShmSysConfigAndInfo->SysInfo.CsuRootFsFwRev, "D0.37.00.0000.00");
+	sprintf((char*)ShmSysConfigAndInfo->SysInfo.CsuRootFsFwRev, "D0.38.00.0000.00");
 
 	// Get AC connector type from model name
 	for(uint8_t idx=0;idx<3;idx++)
@@ -1433,14 +1435,14 @@ void get_firmware_version(unsigned char gun_index)
 	memcpy(&ShmSysConfigAndInfo->SysInfo.CsuRootFsFwRev[14], &ShmSysConfigAndInfo->SysConfig.ModelName[12], 0x02);
 	memcpy(&ShmSysConfigAndInfo->SysInfo.CsuPrimFwRev[14], &ShmSysConfigAndInfo->SysConfig.ModelName[12], 0x02);
 
-	DEBUG_INFO("==================================================\n");
+	DEBUG_INFO("========================================\n");
 	DEBUG_INFO("Model: %s\n", ShmSysConfigAndInfo->SysConfig.ModelName);
 	DEBUG_INFO("CSU hardware version: %s\n", ShmSysConfigAndInfo->SysInfo.CsuHwRev);
 	DEBUG_INFO("CSU boot loader version: %s\n", ShmSysConfigAndInfo->SysInfo.CsuBootLoadFwRev);
 	DEBUG_INFO("CSU kernel version: %s\n", ShmSysConfigAndInfo->SysInfo.CsuKernelFwRev);
 	DEBUG_INFO("CSU root file system version: %s\n", ShmSysConfigAndInfo->SysInfo.CsuRootFsFwRev);
 	DEBUG_INFO("CSU MCU-%2d firmware version: %s\n", gun_index, ShmCharger->gun_info[gun_index].ver.Version_FW);
-	DEBUG_INFO("==================================================\n");
+	DEBUG_INFO("========================================\n");
 }
 
 //===============================================
@@ -2771,19 +2773,23 @@ int main(void)
 					if((ShmSysConfigAndInfo->SysInfo.AcChargingData[gun_index].PilotState == CP_STATE_B) ||
 						(ShmSysConfigAndInfo->SysInfo.AcChargingData[gun_index].PilotState == CP_STATE_C))
 					{
-						ftime(&startTime[gun_index][TMR_IDX_HANDSHAKING]);
 						ShmCharger->gun_info[gun_index].isGunPlugged = YES;
 
 						switch(ShmCharger->gun_info[gun_index].ccsHandshakeState)
 						{
 							case HANDSHAKE_DUTY_5:
-								setRequest(gun_index, ON);
-								setLedMotion(gun_index,LED_ACTION_CONNECTED);	
-								DEBUG_INFO("Set Request On.\n");
-								
-								//Let CCS task start to negotiate
-								ShmCharger->gun_info[gun_index].acCcsInfo.ChargingPermission = ON;
-								ShmCharger->gun_info[gun_index].acCcsInfo.EVSENotification = NOTIFICATION_NONE;
+								if(!getRequest(gun_index))
+								{
+									setRequest(gun_index, ON);
+									setLedMotion(gun_index,LED_ACTION_CONNECTED);
+									ftime(&startTime[gun_index][TMR_IDX_HANDSHAKING]);
+									DEBUG_INFO("Set Request On.\n");
+
+									//Let CCS task start to negotiate
+									ShmCharger->gun_info[gun_index].acCcsInfo.ChargingPermission = ON;
+									ShmCharger->gun_info[gun_index].acCcsInfo.EVSENotification = NOTIFICATION_NONE;
+								}
+
 
 								// Set CCS 5% PWM duty
 								if(ShmCharger->gun_info[gun_index].acCcsInfo.CpSetPWMDuty == CCS_PWM_DUTY_5)
@@ -3022,6 +3028,7 @@ int main(void)
 										ShmCharger->gun_info[gun_index].isCCSWaitChangeDuty = ON;
 									}
 								}
+
 								if((ShmCharger->gun_info[gun_index].isCCSWaitChangeDuty == ON) && ShmCharger->gun_info[gun_index].acCcsInfo.CpSetPWMDuty == CCS_PWM_DUTY_100)
 								{
 									ShmCharger->gun_info[gun_index].primaryMcuCp_Pwn_Duty.max_current = CCS_PWM_DUTY_100;