Writing to text file to Log Debug prints

[Fin]

I've wrote a logger class to log my print statements as I can't debug my gpy+pytrack once I put it into sleep mode with the following code

class Logger():
    def __init__(self,filename):
        self.filename = 'Debug.txt'#filename
        self.isLogging = True

    def write(self,msg):
        if self.isLogging:
            print(msg)
            with open('Debug.txt', 'a') as file:
                file.write(msg)
                file.write("\n")

I'm using atom to upload/download files and I have a blank Debug.txt file in my project. When I go and run my code the logger runs fine. I then try and download the files from gpy back to my project and the Debug.txt file is always empty. So either it's not downloading the file or its not appending to the file. This seems like a really simple thing to code, Im not sure why I'm having issues?

Some more oddities... If I write 'Hello world' in my first line of Debug.txt and then load it to my gpy and then read and print the file its empty...

[John Baird]

@PeterB Ah, there is the difference. Due to the low power requirements of our device we only use deepsleep(), hence the flush was enough for us. Glad you're on the right path now.

[PeterB]

I think I finally found the issue !!!! :)
It does not mean I have a solution for my proposition yet.

When realizing that py.go_to_sleep() cuts the power to the main processor, I thought it might not do it in a nice way while I thought it should.

So I tried machine.deepsleep() instead. YES, than the file is/remains correct and does not contain any garbage and is updated correctly every time!
That means py.go_to_sleep() does not close the 'operating system' running on the main processor in a decent way before cutting its power. That is really really bad!

Knowing this, I do not have a solution yet for my proposition. I need to use the py.go_to_sleep() because I need to reduce power of the pysense for battery consumption reasons AND be able to wake up on accelerometer and on key press (connected to pin 6 of IO connector) of the pysense.

Does anyone know how to close down the main processor nicely without using machine.deepsleep() before I call py.go_to_sleep()?
(if I call machine.deepsleep() before py.go_to_sleep() the py.go_to_sleep() will not be executed)

Or is there any other solution for my proposition?

[PeterB]

I have given it another try, but even with those kind of extensive explicit stuff, it does no work, still garbage in the file:

        file = open(self.filename, 'w')
        file.write("----------------\n"
                    "Logger\n"
                    "New file started\n"
                    "----------------\n")
        file.flush()
        file.close()
        del(file)

[PeterB]

@crumble said in Writing to text file to Log Debug prints:

... So you have to ensure with locks and sleep that your files are written. But this is a general design problem of microPython.

That should be done via "with open" statements, at least within a reasonable time, but even waiting 5 seconds is not enough. I will try once more without the 'with' in the hope that it will than indeed close the file immediately with the explicit close() statement, which is already there by the way, but did not solve the issue.

[PeterB]

@John-Baird said in Writing to text file to Log Debug prints:

@Martinnn Interesting. While I haven't played with the other modes, I assume they are all still available. In our case we want to kill all power to the CPU and all RF devices, including our own GPS. Losing time sync isn't a problem, but it is a pain. Getting battery life above 1 year while staying within the IATA requirements is crucial, so we just went straight for killing the power. Thanks for the link, I'll take a look and do some more research.

2.5 uA too much for keeping the RTC of the ESP32 alive? I can not imagine.
Now we have to add an external RTC: waste of time, money and space.
So Pycom should at least offer the option to keep that alive, possibly next(!) to a full power down of the ESP32 for those who can even not afford the 2.5 uA.

[John Baird]

@Martinnn Interesting. While I haven't played with the other modes, I assume they are all still available. In our case we want to kill all power to the CPU and all RF devices, including our own GPS. Losing time sync isn't a problem, but it is a pain. Getting battery life above 1 year while staying within the IATA requirements is crucial, so we just went straight for killing the power. Thanks for the link, I'll take a look and do some more research.

[crumble]

The behaviour of the PiC is related to a hardwarebug on older LoPy versions where deepsleep drawed too much power.

Every file system can be crashed. Some are more fail save, but you can crash them as well. There are only many flags/events missing which tells if hardware is ready or buffers written/send. So you have to ensure with locks and sleep that your files are written. But this is a general design problem of microPython.

[Martinnn]

@PeterB Here https://lastminuteengineers.com/esp32-sleep-modes-power-consumption/ is a nice overview on ESP32 sleep modes. There are several modes available, the lowest going down to 2.5 uA (and preserving the RTC).
I wonder why they chose the rather crude sledgehammer method of cutting off the ESP32 instead of using the native ESP32 low power modes.
I am also worried about the file thing. I use watchdogs (internal and external) everywhere and if powering down can corrupt the file system (even with flushing), an unexpected reset certainly can do that as well.

[PeterB]

@John-Baird said in Writing to text file to Log Debug prints:

@PeterB I understand your frustration. The RTC failing wasn't really a Pycom choice. To get the power down the power coprocessor turns off the CPU altogether, which has a by-product of completely resetting the device, including the inbuilt RTC. On the plus side, it means you can do things like have a watchdog timer that go into deepsleep for a few seconds and it's close to power cycling the device. That's handy for remote devices. However, I do agree it would be nice if the RTC survived.

The writing to files however, should work and is more of a worry. Are you aware of anyone else having this trouble? I'm asking one of the team here to start working on our own file based buffering solution this week, so I'll let you know what we observe.

Thanks for your reaction. The coprocssor should not turn of the whole ESP32 but switch it to sleepmode in which case the RTC would survive. or at least have that as an option.

Indeed the file writing is a big trouble. Strange thing is that in a another program file writing works and it seems that writing files at another moment after getting out of sleep works. no real idea why.
The main difference between the two I can think of is that the file writing:

• which works is: Done after an accelerometer wakeup
• which does not work is: Done after a button press wakeup (P9/G16)

[John Baird]

@PeterB I understand your frustration. The RTC failing wasn't really a Pycom choice. To get the power down the power coprocessor turns off the CPU altogether, which has a by-product of completely resetting the device, including the inbuilt RTC. On the plus side, it means you can do things like have a watchdog timer that go into deepsleep for a few seconds and it's close to power cycling the device. That's handy for remote devices. However, I do agree it would be nice if the RTC survived.

The writing to files however, should work and is more of a worry. Are you aware of anyone else having this trouble? I'm asking one of the team here to start working on our own file based buffering solution this week, so I'll let you know what we observe.

[PeterB]

As soon as I combine it with go_to_sleep it does not work: explicitely closing the file, flushing, waiting for 5 seconds, not doing the setup for sleep, garbage collection. Really nothing works.

Deepsleep on the pysense is a complete disaster:

• Writing to files before going to sleep does not work as expected. Sometimes it does, sometimes it does not, more not.
• RTC is reset to 0 when waking up, who made that stupid decision?
• Based on the number of questions on the forum it is completley unclear how to minimise power consumption and to which extend.

[PeterB]

@John-Baird said in Writing to text file to Log Debug prints:

@PeterB and it works without the flush. I couldn't get that to happen. Thanks for posting this, I'll try to figure out why it was required in my code.

Now I am not sure yet. It works fine as long as you do not combine it with go_to_sleep. Even adding the flush does not help. It sometimes records garbage in the file.
It looks like the file is not closed properly by the finishing of the 'with open' statement, enabling the go_to_sleep statement to cause rubish in the file to appear. I will try an explicit close on the file tomorrow.

(Please note the go_to_sleep statement is in a totally other part of the program as the 'with open' statement)

[John Baird]

@PeterB and it works without the flush. I couldn't get that to happen. Thanks for posting this, I'll try to figure out why it was required in my code.

[PeterB]

The latest more advanced version:

class Logger():
    def _makenewfile(self, lmsg):
        if self.stdout_enabled:
            print("Logger is creating new file '{}'"
                    .format(self.filename))
        with open(self.filename, 'w') as file:
            file.write("----------------\n"
                        "Logger\n"
                        "New file started\n"
                        "----------------\n")
            if len(lmsg) > 0:
                file.write(lmsg + "\n")


    def __init__(self,
                 filename='Debug.txt',
                 newfile=False,
                 file_enabled=True,
                 stdout_enabled=False):
        self.filename = filename
        self.file_enabled = file_enabled
        self.stdout_enabled = stdout_enabled
        self.RTC = RTC()
        if stdout_enabled:
            print("Logger self.file_enabled: {}".format(self.file_enabled))
            print("Logger self.stdout_enabled: {}".format(self.stdout_enabled))
        if newfile:
            self._makenewfile("")


    def write(self, msg):
        lmsg = msg
        if self.stdout_enabled or self.file_enabled:
            now = self.RTC.now()
            dtg =  ("{:4}-{:02}-{:02}  {:02}:{:02}:{:02}.{:06}  UTC ".
                    format(now[0], now[1], now[2],
                           now[3], now[4], now[5], now[6]))
            lmsg = "[{}]: {}".format(dtg, msg)
        if self.stdout_enabled:
            print("Logger {}".format(lmsg))
        if self.file_enabled:
            try:
                with open(self.filename, 'r') as file:
                    dummy = file.readline()
                with open(self.filename, 'a') as file:
                    file.write(lmsg + "\n")
            except OSError:
                self._makenewfile(lmsg)

[John Baird]

@PeterB There are two ways you could do it.

Firstly you could turn off buffering all together for your debug file. This means any write will be flushed straight away. It will slow down each write a little bit, but won't return to user-space till the write to disk has happened. To do this try changing:

with open('Debug.txt', 'a') as file:

to

with open('Debug.txt', 'a', buffering=0) as file:

Alternatively, you could leave the file buffered, as it is now, and ask the OS to flush the contents of the buffer to disk. To do this, try adding the following:

def flush(self):
        if self.isLogging:
            print(msg)
            with open('Debug.txt', 'a') as file:
                file.write(msg)
                file.write("\n")
                file.flush()

Don't do both as it's a waste of CPU time. Good luck - let me know how you go.

[PeterB]

@John-Baird said in Writing to text file to Log Debug prints:

@Fin I suspect it could be to do with flushing the file to disk. I had the same writing output to stdout just before I went to deepsleep. Adding flush=True caused the write to be flushed and fixed my issue. Is it possible the read has a similar affect ? Worth a try

Where to add that flush=True ?

[John Baird]

@Fin I suspect it could be to do with flushing the file to disk. I had the same writing output to stdout just before I went to deepsleep. Adding flush=True caused the write to be flushed and fixed my issue. Is it possible the read has a similar affect ? Worth a try

[PeterB]

@PeterB said in Writing to text file to Log Debug prints:

Then I would propose:

...

Slightly improved version:

class Logger():
    def __init__(self,
                 filename='Debug.txt',
                 file_enabled=True,
                 stdout_enabled=False):
        self.filename = filename
        self.file_enabled = file_enabled
        self.stdout_enabled = stdout_enabled

    def write(self, msg):
        if self.stdout_enabled:
            print("Logger: {}".format(msg))
        if self.file_enabled:
            try:
                with open(self.filename, 'r') as file:
                    print(file.read())
            except:
                pass  # in case the file does not exist yet
            with open(self.filename, 'a') as file:
                file.write(msg)
                file.write("\n")

[PeterB]

Then I would propose:

class Logger():
    def __init__(self, filename='Debug.txt'):
        self.filename = filename
        self.isLogging = True

    def write(self, msg):
        if self.isLogging:
            print(msg)
            try:
                with open(self.filename, 'r') as file:
                    print(file.read())
            except:
                pass  # in case the file does not exist yet
            with open(self.filename, 'a') as file:
                file.write(msg)
                file.write("\n")