AXS Port Disaster - no DHCP, no FM80, now bricked...

Post Reply
LorenAmelang
Forum Whiz
Posts: 37
Joined: Mon Oct 26, 2009 10:51 pm
My RE system: (being majorly revised...)

AXS Port Disaster - no DHCP, no FM80, now bricked...

Post by LorenAmelang » Sat Aug 23, 2014 5:09 pm

Some of these problems are particular to the Outback Shell app, but the AXS Port should be more tolerant of questionable input.



The OutbackShell app can not tolerate my WIZnet ethernet serial server adding null characters to the TCP stream:
-----
ubuntu@arm:~/Lpkg/axs$ ./shell
OutBack Communications Shell

Version 1.5.0
Type command or 'h' for help
>> c
^@>> c <-- echoed the null and an extra space; I entered <space>c...
^@>> Connect to: 10.1.1.6
^@The IP string is empty <-- simple processing saw only the null
Segmentation fault (core dumped)
ubuntu@arm:~/Lpkg/axs$
-----
Not only does it not work, it segfaults!



The OutbackShell app prompts:
-----
To connect to the default IP address,
enter 'c' then 'd'. Default is defined
as DEF_SERV_IP_ADDR in OutBackShell.c.
-----
Unfortunately the defined address is:
#define DEF_SERV_IP_ADDR "192.168.2.220"
While the actual AXS Port default address is 192.168.0.64.



Once past there, I can connect... At least from a directly wired computer on the appropriate network. While balancing the netbook on top of the inverter in the power shed...
-----
>> c
Connect to: 192.168.0.64
getSunSpecID() Addr 40001 ID 53756E53

SunSpec Device Detected!
Connected successfully to 192.168.0.64
>> r
Block number: 1
Field number (0 to list): 18
192.168.0.64
-----


-----
>> w
Block number: 1
Field number (0 to list): 17
New Value: 1
Write successful
>> r
Block number: 1
Field number (0 to list): 17
Enabled
-----
Turning on DHCP doesn't disable the fixed IP address, so some routers ignore the DHCP Discover request. It was definitely arriving at the DHCP server, and repeated about once every minute, but ignored. This seems to be a gray area in the DHCP spec, but looking at the traffic for hundreds of clients in my neighborhood, only one device is sending an address other than 0.0.0.0 along with a DHCP Discover - and it is being ignored by the bigtime pro router.
-----
2014-08-22 19:17:56.655764 192.168.0.64 255.255.255.255 590 DHCP DHCP Discover
-----
>> e
ERROR: DHCP Failed
-----


So I had to set a fixed address to get the AXS Port onto my network.
Changing the default address reports failure despite working:
-----
>> w
Block number: 1
Field number (0 to list): 18
New Value: 10.1.1.6
Write failed
>> r
Block number: 1
Field number (0 to list): 18
10.1.1.6
-----
Of course the address doesn't _actually_ change until you power cycle the AXS Port... It would be nice if the instructions told you such things.



Once you're connected, there is no actual charge control data block:
-----
>> l
0 SunSpec Common Model Block
1 OutBack AXS
2 SunSpec End Block
>> r
Block number: 2
Field number (0 to list): 0
553 : END_SunSpec_DID
554 : END_SunSpec_Length
>> r
Block number: 3
Field number (0 to list): 0
0 : C_SunSpec_ID
>> r
Block number: 4
Invalid block number
>> r
Block number: 5
Invalid block number
-----

The print manual that came with my Port shows a Charge Controller Block and a Charge Controller Configuration Block, and says they do not work with the MX60. Mine is an FM80... But this is the first I've heard than the AXS Port would not work for an MX60! Of course the print manual is from June 2012, ancient history in the electronics world... The implication has always seemed to be that anything that works with a Mate would work with the AXS Port. I'm gathering from here and from the clues that are coming out about the timing of OPTICSre availability that this is not true.

The AXS Port SunSpec Map.xls from Nov 2012 shows those Charge Controller Blocks, plus blocks for various inverters and FLEXnet-DC. No further clues about which particular device versions are supported.



So then I got curious to try out all the commands... Great until I got to "Unlock". Doesn't sound very scary... I'd assume that if the device isn't locked, it would just say so. But no - if the device isn't locked, "Unlock" tries to lock it! There doesn't seem to be any escape from entering the password, and there is no "Are you sure?" verification before using whatever you entered to lock your AXS Port. Worst of all, there is no filtering of what is a valid password:
-----
>> u
Password:
e



Write successful
>> ^Z
[1]+ Stopped ./shell
ubuntu@arm:~/Lpkg/axs$
-----
I'm not sure what all I tried, but most likely Ctrl+Z and Ctrl+C were included. I also don't remember what ended the password entry and wrote it to memory - probably <Enter>. After the write, the AXS Port and the Shell app were both unresponsive, and I finally ended the Shell program with Ctrl+Z.
-----


Trying again...
-----
ubuntu@arm:~/Lpkg/axs$ ./shell
OutBack Communications Shell

Version 1.5.0
Type command or 'h' for help
>> c
Connect to: 10.1.1.6
Connection failed: Connection timed out
Connection failed
>> >> Not currently connected.
-----
Given a very long time (minutes), the connection attempt eventually does time out by itself. (I left it sitting there waiting while I went out to the power shed with the netbook to reset the AXS Port.) No reasonable user would wait that long.


I have not been able to connect since, but even if I had, the instructions are wrong:
(From the README file for the OutbackShell):
-----
To disable these security features, after unlocking using the current password, write "NULL" to the password field.
-----

In the actual program:
-----

Code: Select all

case 'U':
case 'u':
	if (0 != connected)
	{					
		printf("Password: ");
		scanf("%s", buff);
		if ((0 == strcmp(buff, "clear")) || (0 == strcmp(buff, "CLEAR")))
		{					
			if (1 == writeSunSpecRegister(1, OutBack_Write_Password, 0))
			{
				printf("Password cleared\n");
			}
			else
			{
				printf("Password clear failed\n");
			}
		}
		else
		{
			if (setFieldWithString(1, OutBack_Write_Password, buff))
			{
				printf("Write successful\n");
			}
			else
			{
				printf("Write failed\n");
			}
		}
	}
	else
	{
		printf("Not connected\n");
	}
	break;
-----
Looks like the magic entry is "CLEAR", not "NULL".

--> Using sscanf to process user input of a password, and doing no further processing or verification of the resulting string is a recipe for disaster.
I haven't studied the whole sequence, but I see the input buffer used in the above code is 64 bytes:
char buff[64];
While the target password field is 16 bytes:
Outback_Write_Password String (16)
I'm not seeing any code to resolve that pending disaster. Which obviously struck me.



After writing the disastrous password, the SunSpecID is wrong, and different each time:
-----
>> c
Connect to: 10.1.1.6
getSunSpecID() Addr 40001 ID 53751060
getSunSpecID() Addr 40001 ID 53751060
ERROR: SunSpec Device NOT Detected
Connection failed
>> c
Connect to: 10.1.1.6
getSunSpecID() Addr 40001 ID 5375084C
getSunSpecID() Addr 40001 ID 5375084C
ERROR: SunSpec Device NOT Detected
Connection failed
>> c
Connect to: 10.1.1.6
getSunSpecID() Addr 40001 ID 5375E9DC
getSunSpecID() Addr 40001 ID 5375E9DC
ERROR: SunSpec Device NOT Detected
Connection failed
>> c
Connect to: 10.1.1.7
Connection failed: No route to host
Connection failed
>> c
Connect to: 10.1.1.5
Connection failed: Connection refused
Connection failed
>> c
Connect to: 10.1.1.6
getSunSpecID() Addr 40001 ID 53758514
getSunSpecID() Addr 40001 ID 53758514
ERROR: SunSpec Device NOT Detected
Connection failed
-----
It is obviously talking to the right address, but reading the wrong SunSpecID - and a different one each time!



So I was down to resetting factory defaults:
-----
You can also reset the device using the reset switch to reset all values to their defaults, which includes removing the password and disabling the security features.
-----

No such luck! The error light flashed about ten times rapidly, and then stopped, but there was no apparent reset. A following power cycle reset the default IP address, but I still couldn't connect due to the wrong and variable SunSpec ID.

Another reset triggered a chasing pattern along the left ethernet LED, the error LED, and the SD LED. Repeated about every two seconds, for minutes, I gave up waiting. Nothing done with the reset button changed it. One time removing and replacing the SD card stopped it and actually let me try to connect, but I still encountered the bad ID.

Back when I could connect, there seemed to be an ID field in a block beyond the listed blocks:
-----
l
0 SunSpec Common Model Block
1 OutBack AXS
2 SunSpec End Block
>> r
Block number: 2
Field number (0 to list): 0
553 : END_SunSpec_DID
554 : END_SunSpec_Length
>> r
Block number: 3
Field number (0 to list): 0
0 : C_SunSpec_ID
-----
Would be interesting to see what is there now, but I can't connect at all.



So I tried the firmware update. Putting AXPorte.bin in the UPDATEFW folder does not work for a power cycle update - I got the same chasing pattern of LED flashes, with a tiny flash of the SD LED in between each pattern while the reset button was held, for as long as I was willing to wait. It would be nice if we were told what that pattern means - it is obviously intentional.

Rather than make more trips back and forth to the power shed, I just put AXPorte.bin, \AXS PORT UPDATE\AXS Port_V001_005_000_update\AXPorte.bin, and the actual download - \AXS_PORT_UPDATE_REV_D\AXS PORT UPDATE REV D\AXS_PORT_Firmware,_Version_001.005.000.zip\AXS PORT UPDATE\AXS Port_V001_005_000_update\AXPorte.bin all on the top level of the card and let it pick. One of them worked... The SD LED blinked rapidly, about nine times, and it was done in seconds. It would be nice if we were told exactly which version of the update file to put where.

So now I'm back to the variable and wrong SunSpec ID problem. The last half of the value is different every time I try to connect, and always rejected. Guess I'm not going to solve this one today...


Turns out this is a known bug - since at least February!
<viewtopic.php?f=41&t=7428&p=42831&sid=3 ... 153#p42831>

Apparently setting any password from any app bricks the AXS Port...



Along with a few seconds of log data from 2 Jun and 14 Jul, my SD card has two minutes of new log data with a time before it was connected to the network. It is set to my time zone, but of course it may not understand DST, so who knows when those two minutes actually were. The new data has the same format as the old files, no header line, nothing like the Charge Control example in the manual. (I guess that's a daily summary...)

After the firmware update, I'm getting longer log files. It can't do NTP with the default IP address, so the dates are random. It does sort-of match the "system" example, but with only a charge controller some of the items are odd. It shows date, time, always port 0, device type 3, invrt current 0, charge current 7 (probably 7A DC, but stays at 1 at night), buy current 1 (0 at night ?), AC input V 122 (probably DC input V), AC out V 29 (47 at night ???), sell current [variable 1-6] (?), operating mode 3, error mode 0, AC mode 1 (2 at night), battery V 27.2 (seems right), misc 105 (but 172 at night ?), warning mode 0. Would be nice if these were documented...
Last edited by LorenAmelang on Mon Sep 08, 2014 1:05 pm, edited 1 time in total.

LorenAmelang
Forum Whiz
Posts: 37
Joined: Mon Oct 26, 2009 10:51 pm
My RE system: (being majorly revised...)

Re: AXS Port Disaster - no DHCP, no FM80, now bricked...

Post by LorenAmelang » Mon Aug 25, 2014 12:28 pm

I just thought to go look through my logs - turns out the firmware I loaded from the web was not an update:

*** SunSpec Common Model Block ***
0 : C_SunSpec_ID 1850954613
1 : C_SunSpec_DID 1
2 : C_SunSpec_Length 65
3 : C_Manufacturer OutBack_Power
4 : C_Model AXS_PORT
5 : C_Options
6 : C_Version 001.007.000
7 : C_SerialNumber AX1424F0100045
8 : C_DeviceAddress 1

The "AXS_PORT_Firmware,_Version_001.005.000" they offer on the web is older than what came on my AXS Port! I guess that means they _still_ haven't fixed the bug...

LorenAmelang
Forum Whiz
Posts: 37
Joined: Mon Oct 26, 2009 10:51 pm
My RE system: (being majorly revised...)

Re: AXS Port Disaster - no DHCP, no FM80, now bricked...

Post by LorenAmelang » Tue Sep 02, 2014 1:20 pm

My first attempts above to decode the uSD log format were way off track. For a much more helpful presentation, look here:
viewtopic.php?f=41&t=7617

LorenAmelang
Forum Whiz
Posts: 37
Joined: Mon Oct 26, 2009 10:51 pm
My RE system: (being majorly revised...)

AXS Port Disaster - 005 Firmware better, but time chaotic

Post by LorenAmelang » Fri Oct 03, 2014 4:28 pm

Apparently OutBack support is hopelessly overloaded. It took two entire weeks and blasting an eMail to a half-dozen OutBack addresses to get their attention. They shipped a new AXS Port with 001.007.000 firmware. It showed the same OutBack blocks as the previous one did before it was bricked, but no charge controller blocks, and no updates to time or temperature fields. And no logging to the uSD card.

After another couple of weeks on ignore, OutBack support convinced me I had nothing to lose by loading the web-provided 000.005.000 firmware to the new AXS Port, even though there is no provided way to get back to 007. I loaded 005, and it worked immediately without a power cycle! And it shows charge controller data! I didn't have 005 on the old AXS Port until after it was bricked, so I never saw this condition. It initially showed the date I set manually weeks ago, that 007 would never show.

Setting it to my network and power cycling made it work there. Plugging it back into the bridge let NTP fix the time - apparently the
44 : OutBack_Enable_Time_Server Disabled
line applies to a server function in the AXS, rather than its client access to outside time.

But the time remains confused. Here is the first 005 run, that showed the time I set via 007, entering local clock time in the Shell:

49 : OutBack_Year 2014
50 : OutBack_Month 9
51 : OutBack_Day 24 <-- date is correct
52 : OutBack_Hour 10 <-- had set local time via Shell
53 : OutBack_Minute 5 (now showing 8 hr early from local)
54 : OutBack_Second 41

When 005 could access the net, NTP changed that time by eight hours:

49 : OutBack_Year 2014
50 : OutBack_Month 9
51 : OutBack_Day 24
52 : OutBack_Hour 18 <-- NTP time = actual clock time
53 : OutBack_Minute 23 <-- probably 18 min elapsed
54 : OutBack_Second 54

By Oct 29, the time was _days_ wrong. Apparently NTP only happens when the AXS program starts up...??? The FM80 has been zeroing its daily accumulations at about 5 PM every day, as if it thought 5PM was midnight - which matches the +7 hour offset:

49 : OutBack_Year 2014
50 : OutBack_Month 10
51 : OutBack_Day 1
52 : OutBack_Hour 3 <-- 8:04PM 0929; +7 hr +1 day
53 : OutBack_Minute 4
54 : OutBack_Second 53

Just leaving the Shell idle and trying again 11 minutes later, it shows eight hours have been added!

49 : OutBack_Year 2014
50 : OutBack_Month 10
51 : OutBack_Day 1
52 : OutBack_Hour 11 <-- 8:15PM (added 8 hours)
53 : OutBack_Minute 16
54 : OutBack_Second 0

No more jumps were added in the next hour that I watched it. I manually set the correct local time shortly after that, and it is still reading correctly 14 hours later. I'll be watching...


Here is a time jump in the first AXS Port with 005, as shown in the uSD log. Note the 8-hour time difference in the middle of this block... The "4/26" date is entirely random, as were all the dates logged by the bricked AXS Port after I loaded 005. Maybe this is a previous manual time change? Or maybe another mystery offset?
---
4/26/14,13:27:52,00,3,00,07,02,122,029,09,03,000,01,272,0105,00
4/26/14,13:27:53,00,3,00,08,02,122,029,00,03,000,01,272,0105,00
4/26/14,21:27:56,00,3,00,08,02,121,029,00,03,000,01,272,0105,00
4/26/14,21:27:57,00,3,00,07,01,121,029,09,03,000,01,272,0105,00
---


The "extra block" my previous post thought existed beyond the listed ones is probably an artifact of the shell program:
---
>> l
0 SunSpec Common Model Block
1 OutBack AXS
2 OutBack System Control
3 Basic Charge Controller
4 OutBack FM Charge Controller
5 SunSpec End Block
>> r
Block number: 5
Field number (0 to list): 0
553 : END_SunSpec_DID
554 : END_SunSpec_Length
>> r
Block number: 6
Field number (0 to list): 0
0 : C_SunSpec_ID
>>
---
You can't list field 0, because 0 lists all the fields. When you try to read a block beyond the available numbers, it looks like it wraps around to the beginning offset value...


The first (now obsolete) version of the official SunSpec Tool is open source on GitHub:
<https://github.com/jdblair/sunspec>

If you use the recommended older version of libmodbus, you can build it and it sort-of works. I found it produced fewer errors if I used the "-vvv" parameter.

The included equipment maps for the FM80 are obsolete and do not show all of the items in the current blocks. But the tool does read the same wrong and variable SunSpec ID from the bricked AXS Port, confirming it is unusable. The Tool can provide a simulation of a system with an FM80 and an inverter, from which it reads back appropriate SunSpec blocks. Trying to use the OutBack Shell app to read the simulation produces wrong SunSpec ID values - but the same wrong values each time. Not the random SunSpec ID problem seen when trying to read the bricked AXS Port.


I chose to grab the data I want via Python:
<git://github.com/bashwork/pymodbus.git>

There is a "contributed" example of a SunSpec client, which includes a map for the common block but no equipment maps. I've made my own FM80 maps, with the help of the Suns Tool maps and the OutBack Shell output.
<https://github.com/bashwork/pymodbus/bl ... _client.py>


There's a vaguely interesting thread on the MidNite Solar forum about using the AXS Port to talk to their Classic charge controller:
<http://midniteforum.com/index.php?topic=1750.0>
It shows a fancy graphic but proprietary Windows software package, a bit of which is offered for free download. Doesn't talk to OutBack charge controllers. Interesting discussion of trying to insert various ethernet hub devices on the OutBack bus side of the AXS Port - somebody doesn't understand that not everything with an RJ45 speaks ethernet! Of course OutBack has been rather secretive about what exactly _is_ transmitted on their proprietary bus.


Of all the FTP clients I tried to use to download the uSD log files, only the ancient WS_FTP from Win95 days was able to connect. ... I later installed the suggested FileZilla (on Linux) and it worked perfectly. Firefox connects but shows nothing at all in the / directory. Chrome and Opera timeout. It is just ordinary anonymous FTP, I'm surprised browsers can't do it.



I tried to post this days ago, but the OutBack forum wouldn't let me post anywhere. Maybe just as well, I have more info about the time problem now.

I just studied the uSD logs created since I loaded the 005 firmware. Clearly there is a nasty time problem, but I don't see a simple explanation - except that all of the time glitches happen during the night (despite the logged times), while the logged data clearly show my FM80 is not charging! The time keeps arbitrarily jumping ahead, usually by exactly eight hours. Typically a log file ends early, and the next log file begins at the next second plus eight hours.

All of the file sequence 14093003 through 14093019 (16 hours...) are double the size of a normal file, and cycle through the same hour twice, with different data. Several other single files also cover the same hour twice, but one half begins late or ends early.

--> Aha! That happens when the time has wrongly jumped ahead, and I manually reset it back to the proper time. When it gets to the wrongly timed existing files, it just appends to what was already there.

Several files are smaller than normal size, including those surrounding the 8hr jumps and a few others.


Here's a sample of the sequence of log files, including the modbus session:
---
9/28/14,10:47:14,00,3,00,00,00,018,060,00,03,000,00,255,0218,00
9/28/14,10:47:15,00,3,00,00,00,018,060,00,03,000,00,255,0218,00
file ends, +8hr, new file
9/28/14,18:47:16,00,3,00,00,00,018,060,00,03,000,00,255,0218,00
9/28/14,18:47:17,00,3,00,00,00,018,060,00,03,000,00,255,0218,00
... continuous logging
9/29/14,18:57:34,00,3,00,00,00,018,047,00,03,000,00,255,0169,00
9/29/14,18:57:35,00,3,00,00,00,018,047,00,03,000,00,255,0169,00
file ends early, gap in time and +2hr:

--> According to the logged time and my local clock time, this is when
I was looking at the modbus reports. Modbus was reporting the time +1 day +7hr:
--> But right now, both the uSD log time and modbus time are +1 day
(1004 instead of the actual 1003) and match exactly...
(So I suspect this is not the log of the modbus session...)
-----
49 : OutBack_Year 2014
50 : OutBack_Month 10
51 : OutBack_Day 1
52 : OutBack_Hour 3 <-- 8:04PM 0929; +7 hr +1 day
53 : OutBack_Minute 4
54 : OutBack_Second 53

Just leaving the Shell idle and trying again 11 minutes later, it shows eight hours have been added!

49 : OutBack_Year 2014
50 : OutBack_Month 10
51 : OutBack_Day 1
52 : OutBack_Hour 11 <-- 8:15PM (added 8 hours)
53 : OutBack_Minute 16
54 : OutBack_Second 0
-----

previous file ended early, gap in time and +2hr:
9/29/14,21:00:00,00,3,00,00,00,018,000,00,03,000,00,254,0002,00
9/29/14,21:00:01,00,3,00,00,00,018,000,00,03,000,00,254,0002,00
... [continuous logging through the time modbus was reporting as glitch time]
--> But that was probably the second pass, after I set the time back a day!
--> In "14100111 similar, but first half starts late, ends early" below,
the period just after the above modbus interaction is logged in the
first half of the file, followed by a clean second half when it was
actually that time.
10/02/14, 4:41:20,00,3,00,00,00,018,000,00,03,000,00,252,0002,00
10/02/14, 4:41:21,00,3,00,00,00,018,000,00,03,000,00,252,0002,00
file ends, +8hr, new file
10/02/14,12:41:22,00,3,00,00,00,018,000,00,03,000,00,252,0002,00
10/02/14,12:41:23,00,3,00,00,00,018,000,00,03,000,00,252,0002,00
... continuous logging
10/03/14,12:56:55,00,3,00,00,00,018,043,00,03,000,00,253,0156,00
10/03/14,12:56:56,00,3,00,00,00,018,043,00,03,000,00,253,0156,00
file ends, +8hr, new file
10/03/14,20:56:57,00,3,00,00,00,018,043,00,03,000,00,253,0156,00
10/03/14,20:56:58,00,3,00,00,00,018,043,00,03,000,00,253,0156,00
---


If uSD time = modbus time, here's the sudden file end during the modbus session:
10/01/14, 3:10:57,00,3,00,00,00,018,000,00,03,000,00,252,0002,00
10/01/14, 3:10:58,00,3,00,00,00,018,000,00,03,000,00,253,0002,00

And here's the +8 hr jump...
14100111 similar, but first half starts late, ends early:
--> First half of file during and after the modbus interaction shown above!
10/01/14,11:10:59,00,3,00,00,00,018,000,00,03,000,00,253,0002,00
10/01/14,11:11:00,00,3,00,00,00,018,000,00,03,000,00,253,0002,00
... continuous logging
10/01/14,11:48:10,00,3,00,00,00,018,000,00,03,000,00,254,0002,00
10/01/14,11:48:11,00,3,00,00,00,018,000,00,03,000,00,254,0002,00
--> Second half is a clean log from the next pass through that time:
10/01/14,11:00:00,00,3,00,00,00,018,038,00,03,000,00,251,0137,00
10/01/14,11:00:01,00,3,00,00,00,018,038,00,03,000,00,252,0137,00
... continuous logging
10/01/14,11:59:58,00,3,00,00,00,018,038,00,03,000,00,252,0137,00
10/01/14,11:59:59,00,3,00,00,00,018,038,00,03,000,00,251,0137,00


So my current conclusion is that log time matches modbus reported time. When the time has jumped ahead, and is set back to proper time, logs for time periods that were first recorded at the wrong time get the data for the correct time period appended.

I really did happen to be logged into the Shell program on modbus while one of the time jumps occurred. Both indications of AXS time agreed, and were wrong.

And most obviously, all of this time chaos takes place during the night, while my FM80 is not charging!

Could the AXS somehow be responding to the FM80 automatic reset when a new day starts? Probably not the explanation, since it doesn't jump every night. Maybe it only jumps if the reset happens at certain times on the AXS clock?

Certainly makes the logs frustrating! As do the null characters in the log files, that TextPad can't copy. Does anyone know the details of what these do?
OutBack_SD_Card_Log_Write_Interval
OutBack_SD_Card_Log_Retain_Days
OutBack_SD_Card_Logging_Mode


So... Has anyone with an AXS Port figured out the time issue?

Do you set local time or UTC? In which firmware version?

Does it understand daylight saving time? Do you leave your winter offset value in the TimeZone field all year, or do you have to manually change it every spring and fall?

Maybe it depends on what equipment you have connected?

Is there some way to make NTP check periodically to keep the proper time set?

LorenAmelang
Forum Whiz
Posts: 37
Joined: Mon Oct 26, 2009 10:51 pm
My RE system: (being majorly revised...)

Yet More Date/Time Confusion!

Post by LorenAmelang » Sat Nov 15, 2014 1:24 pm

I ran into a mystery with another part of my system today, that probably could have been cleared up by seeing the appropriate bit of the AXS Port log. So I tried to position my attention into the chaos of its time problem. It is more complex than I thought...

I'm writing this on 141112. Since 141005 21:00 (positively identified by watching the file created), there are 733 new files in my uSD. By the calendar that is 31+7 or 38 days *24 hours, so there should be 912 files, minus 3 because it was only 18:00 tonight, not 21:00 when I counted. Of course every 24:16 an extra file is created when the time jumps ahead eight hours, so not quite 38 of the existing files are for hours already represented.

The difference between 912 - 3 = 909 and 733 - 38 = 695 is 214 hours that are not logged, or 5.6 hours per day. Seems it should be eight hours???

Except for the eight hour jumps, the sequence of filenames is continuous. By the filename times we've gone from 141007 13:00 to 141115 03:00 (plus 3 files that got named 141126 after I power cycled the AXS Port tonight...), so 38.5 days - pretty much correct. So it looks like it is just not logging to uSD during the eight hour jumps.

Except the lost data breaks are not neatly located where the filename time jumps are! I'd expect they would be between the partial file before the jump and the remainder of the hour after the jump, but no, the actual data is usually continuous across that break. If you follow the sequence of amp-hours logged, the sudden breaks may be anywhere in the sequence of apparently contiguous filenames! I had missed that before, concluding that since the data was continuous across the eight hour jumps that none was being lost. And of course given my file count exercise, not all of the eight hour jumps result in eight hours of data loss, the average must be under six hours lost.

The new discovery tonight is that the date in the filenames maintains a proper 24-hour sequence (with gaps), while the date reported by a SunSpec query actually does jump ahead by the eight hours a day. SunSpec has been reporting today was Nov 26th, and after my power cycle the uSD log filenames moved to the 26th. But the filenames before the power cycle were Nov 15, about the same offset from the correct Nov 12 as the previously reported 141007 filename for the real date 141005.

So there are two separate dates in the AXS Port, one that counts hours properly but fails to log some of them, and one that jumps ahead eight hours per day and gets wildly out of sync with the calendar. After a power cycle with NTP disabled, the filenames adopt the SunSpec version of the date. With NTP enabled, both SunSpec and filenames have adopted the correct time upon power cycle. Will be interesting to see how long that lasts.

I could swear I saw NTP work before, while the SunSpec setting was at the default disabled value. According to my previous post above here, that happened when I powered up the AXS Port without a network connection, and then plugged in the cable. Could that produce a different result from having the network available during a power cycle? At this point it appears NTP must be Enabled in the OutBack Block.


I first tried to FTP the log files, but the FTP server reset the connection before listing the filenames, even with FileZilla or WS_FTP. That's why I cycled the power, and it did fix the FTP - for awhile. Except that it was running at a hopelessly ridiculous speed of 144 kbps on a connection that should handle at least 8 Mb. After a couple of hours of that it just reset and refused to connect again. Since I'd have to visit the power shed anyway, I just grabbed the files off the uSD directly.


It is now 141115, and I have two and a half days of logs with no eight hour jumps in filename or in actual data, and the SunSpec time is still correct. What made the difference? It could be setting OutBack_Enable_Time_Server to Enabled. Or it could be setting OutBack_SD_Card_Log_Write_Interval to 60 instead of the default 1 second value. Given the hopelessly slow FTP speed, I decided smaller log files would be better.

They would be even better if a day wasn't divided among 24 separate 3960 byte files. Of course the 007 firmware went to the opposite extreme, I never saw it start a new file (except for power cycles) in the short time it was functional. It made a 48 MB single file, and probably would have kept going!

I wonder if OutBack_SD_Card_Logging_Mode affects that? It has always been '1', but maybe 005 and 007 interpret that differently? Searching the web for clues gets me only my own post...

LorenAmelang
Forum Whiz
Posts: 37
Joined: Mon Oct 26, 2009 10:51 pm
My RE system: (being majorly revised...)

Re: AXS Port Disaster - no DHCP, no FM80, now bricked...

Post by LorenAmelang » Sat Nov 22, 2014 10:25 pm

Now proven - setting OutBack_Enable_Time_Server to Enabled hides the eight hour time jump problem. When I re-enabled it, the time corrected itself immediately, for both filenames and SunSpec queries.

WS_FTP has been working for the shorter, 60 second interval files, except it can only get about a day's worth before it gets an error and stops. If I re-select the next files, it starts again.

Firefox connects and the AXS actually gets as far as sending back the first directory listing:
FTP Data: d-------- 1 owner group 0 Sep 11 04:33 DATALOGS
but Firefox displays a blank directory instead of "DATALOGS", and the connection just stalls there.

The line ending for that directory line arrives in the following packet:
FTP Data: \r\n
I wonder if that confuses Firefox? It just reports "error loading source".

Post Reply