Memory allocation failed

[MartiMan79]

I'm trying to access a log file over HTTP on a Pico W but getting mem errors.

File size: tried from 80k down to 30k maxBytes in the RotatingFileHandler settings but to no avail.

I've read about excessive fragmentation but to me it appears that's not the case as "76 lines all free"?

Code starts with:

async def serve_client(reader, writer):
    
    
    try:
        print("Client connected")
        request_line = await reader.readline()
        print("Request:", request_line)

# We are not interested in HTTP request headers, skip them
        while await reader.readline() != b"\r\n":
            pass
        gc.collect()
        m = gc.mem_free()
        print(micropython.mem_info(True))
        info = os.stat("/debug.log")
        filesize = info[6]
        print('File size = ',filesize)
        print('mem free', m)

        etc...

Any ideas?
Thanks in advance.

Request: b'GET /log HTTP/1.1\r\n'
Client connected
stack: 1300 out of 7936
GC: total: 189952, used: 52448, free: 137504
 No. of 1-blocks: 582, 2-blocks: 173, max blk sz: 122, max free sz: 4955
GC memory layout; from 20011a00:
00000000: MDMLhhhSMDhhDLSDBBBBhDhhh===MDBDh====B=BBBBBBDB=BhB=BBB.B=DBDB=B
00000400: h===hB=h===========B=.MDSh===================h========h=========
00000800: ========h=======================================================
00000c00: ========h=======================================================
00001000: ========h=h=hhhBBMBDSDSSDBMDhhDShTShhBh==.TSh=MD.BDh=.DSh=======
00001400: hTD.h==SSh=======h========BBDh===h==BBh=h===hhhDB=BSBh==DDBBBh==
00001800: h==h=======BBBBBBBBBBBBBBBBh========BBBh================Bh===BB=
00001c00: B==DBBBDh=======Bh==h===hh==h=======SBBB=hBBBh==DhhDhBB=h=h===h=
00002000: =h===hShhhhh=============BB=B=hhDhBh==h===DBBDSBhSh==h=BBBSh====
00002400: ===h=======hSSh=B=BhBB=h===h====hBBh=h=h==================Lh=hBS
00002800: Dh==SSBhBhBSh==h===SBBBh===hDB=hhhh=Bhhhh=DTDhh====hhhhhhBBh=B=h
00002c00: hh===Dhh=hhhhh===hBhLh===h=Lhhhh=B=h=BBh========================
00003000: =======h===hSh====h==h=====hh=h==h===hMDSh===hhh...hhSThh=.hhhAh
00003400: ===hLhh==.h=.SSh=h===========T=Shhh==============h=h=hhBBhh=====
00003800: ==ShSh=h=SSShh====h=SLh=h==================hShh=h=h=h=hh=======B
00003c00: hh===hDh.BhhhSh===h=Dhh=hhBBhSSh==h.h=hSh=hh=h=h.Sh=Fh=h========
00004000: ======Sh=h========h===..B.Mh==h=============h====h======S.D..h==
00004400: h.h.ShS......MD..Bh====hSShh====================================
00004800: =========================h=======hSh=.h...h==SSSh==SST...h=h====
00004c00: =====.MD.hBhDSSh==Sh==hSSSh==..hhSh=h=BBB.Bh===h==h===MDhShF....
00005000: D.h=hB..B.Fh===h==.......................h===...................
00005400: .....................................................h==hTD.....
00005800: .................................hBBhh=h=B==....BBB.........h=..
00005c00: BBBBBBBBB.Sh==Sh=....S.hSBBh===h===.Sh=.h===========h========.Sh
00006000: =======Sh=h.h=h=S...h=S.SSh=..h=...h=h=====S..SSh=....h=FSh==h=h
00006400: hhh==ST=hMh==hMD...h=DBBhhBhDhh.....Sh=ShS.h==BBhhhhhBhhh=Sh==..
00006800: ............D.h=======BD.h===h===B=h.Bhhhh=h=======h============
00006c00: ========================h=======Sh=h=h=h=ShSh=Sh=Sh=BhD..T......
00007000: .............FhSh.hh=hShh===hhBh=..h=TThSSh=.Sh=h===============
00007400: ===.h=Thh===SSShh===.h=h====h====Sh=h=h=Sh=h========......hh..Sh
00007800: ======.........h=h=Shh=h=======h=h=======SSh==h=h=======Sh.....S
00007c00: .h=Sh=hSSh=========..........h=h=======================.........
00008000: ...............h==................h==h=Fh=.h===h=====...........
00008400: ....hSh=h=h=hh=====hh=hh=h=h=h=h=h===h=h==hhh==h==h=h=Shh===h==h
00008800: ==h==h========h==hhh===hh=h======h=======.h===============hS....
00008c00: ...h==h=hh=======h=h...........h................................
00009000: ................................Sh.........ShSh==..h=ShShSShSh=S
00009400: h=Sh=ShSh=Sh=Sh=======================================h=........
00009800: .....h.......h=h=Sh=..........SSh.........hhSh==..........SSh==.
00009c00: ................................................................
0000a000: ...........................h====......................h=Sh......
0000a400: .......h===========..............................h=h=h=hh==h==h=
0000a800: h=============h=================================h========h=h=h.h
0000ac00: ===========================h=======================h====h=====h=
0000b000: ========h===h==========h===============h===h=========h==h======h
0000b400: ===Sh=================================================h=========
0000b800: ============h===========h=====h====h==h==h========..............
0000bc00: ......................................h=========================
0000c000: ============================h===================================
0000c400: ===================h===================================.........
       (4 lines all free)
0000d800: ..h=====h=h=====h=h====h=h===h=......h..........................
       (2 lines all free)
0000e400: ..........h=====================================================
0000e800: ================================================================
0000ec00: ====............................................................
       (8 lines all free)
00011000: ......h=======..................................................
00011400: ................................................................
00011800: ..................h=.............h=............h=...............
00011c00: .....h=.........................................................
00012000: .............SSh=...............................................
00012400: ................................................................
00012800: ........h........S..............................................
00012c00: .................................h=======.......................
00013000: ..............................................h====.............
00013400: ................................................................
00013800: .....................................................h=.........
00013c00: Sh=..........Sh=.............Sh=................................
00014000: ..........................................Sh=...........Sh==....
       (2 lines all free)
00014c00: .....................................Sh=........................
00015000: ........h=====================================.........Sh=......
       (2 lines all free)
00015c00: .Sh==..............Sh.........Sh=..................MD.Sh=Sh==...
00016000: ................................................................
00016400: ....................BBDBBBhBhBBBBh===h===...B==B..............h=
00016800: =======.........................h=...hh...............h=....h=..
00016c00: h=...............h=..........h=....h=.........................h=
00017000: ................................................................
00017400: ................................................h...............
       (3 lines all free)
00018400: .........h==h===....................h===h====h===h==============
00018800: ==================h===h===============h==========h===h====h=====
00018c00: h==============h===.............................................
       (2 lines all free)
00019800: ...............h=......h========================================
00019c00: =====h=======h=========h====h==================h============h===
0001a000: ===============h===h============================================
0001a400: ==================h=======h===============================h=====
0001a800: =======================h========h======h====h===h==h====h=======
0001ac00: =======h=====h====h=====h=======================================
0001b000: =====...........................................................
       (76 lines all free)
0002e400: ................................
None
File size =  45404
mem free 137504

[peterhinch]

Please explain what you are doing with the data you're reading. Does the entire dataset need to be contained in RAM? In what format are you storing it? Bear in mind that Python strings are immutable: string operations can result in fragmentation.

Without knowing your application it's hard to make recommendations, but I would consider parsing the data in blocks (line by line?) - perhaps reducing it to summary information before discarding the raw data before moving on to the next block.

[MartiMan79]

Dear Peter, thanks for the reply.

And also a big thanks for all of your work that makes my little project possible!

Maybe it's better to show my code as I'm a newbie coming from automation PLC with some basic SCL experience.

I assembled this code from various sources and got it to work (except the logfile access through HTTP)
It's an MQTT_AS stepper config for a sun following Pergola with "dimmer function".
I also implemented OTA updating from my Github repo running on a Pico W.

Forgive me if my code looks hideous, it works though lol.

I do logging to 3 files:

• data.txt for machine up times
• errorlog.txt for exceptions
• and debug.log for operational log

gc.collect() runs in the main loop in motion().

The debug.log is rotating with a max file size with 3 backups.
The other ones I haven't found out yet lol (I suspect a new file generated per day).
I know I'm having 2 separate logging functions, still deciding which one to keep as main.

But the main issue is accessing a file located in the ROM through an HTTP request.

from log import logger
import machine
from machine import Pin, RTC
from mqtt_as import MQTTClient, RP2
from mqtt_local import config
import network
from ntptime import settime
import os
from ota import OTAUpdater
from stepper import Stepper
import sys
import uasyncio as asyncio
import time


if RP2:
    from sys import implementation
    

# define motor controller pins
s1 = Stepper(18,19,steps_per_rev=96000,speed_sps=1000)
disable = Pin(20, Pin.OUT)
endswitch = Pin(22, Pin.IN, Pin.PULL_UP)
alarm = Pin(17, Pin.IN, Pin.PULL_UP)
LED = machine.Pin("LED",machine.Pin.OUT)
rain = Pin(16, Pin.IN, Pin.PULL_UP)


# Default  MQTT_BROKER to connect to
#MQTT Details
GROUP_ID = config["group_id"]
CLIENT_ID = config["client_id"]

SUBSCRIBE_TOPIC1 = str(CLIENT_ID)+"/set_angle"
SUBSCRIBE_TOPIC2 = str(CLIENT_ID)+"/status"
SUBSCRIBE_TOPIC3 = str(GROUP_ID)+"/general"
PUBLISH_TOPIC1 = str(CLIENT_ID)+"/status"
PUBLISH_TOPIC2 = str(CLIENT_ID)+"/actPos"
PUBLISH_TOPIC3 = str(CLIENT_ID)+"/info"
PUBLISH_TOPIC4 = str(GROUP_ID)+"/general"

# Global values
gc_text = ''
DATAFILENAME = 'data.txt'
LOGFILENAME = 'debug.log'
ERRORLOGFILENAME = 'errorlog.txt'

# Variables
homingneeded = True
pos = 0
setangle = 0
oldTime = 0
currentTime = 0
rssi = -199  # Effectively zero signal in dB.
raining = False
oldval = 0
connected = False

# HTML file
html = """<!DOCTYPE html>
<html>
    <head> <title>Pergola controller #2</title> </head>
    <body> <h1>Pergola shading control #2</h1>
        <h3>%s</h3>
        <h4>%s</h4>
        <pre>%s</pre>
    </body>
</html>
"""

async def log_handling():
    
    global connected
    global timestamp
    
    local_time = time.localtime()
    record("power-up @ (%d, %d, %d, %d, %d, %d, %d, %d)" % local_time)
    
    try:
        
        y = local_time[0]  # curr year
        mo = local_time[1] # current month
        d = local_time[2]  # current day
        h = local_time[3]  # curr hour
        m = local_time[4]  # curr minute
        s = local_time[5]  # curr second
        
        timestamp = f"{h:02}:{m:02}:{s:02}"
        
        # Test WiFi connection twice per minute
        if s in (15, 45):
            if not connected:
                record(f"{timestamp} WiFi not connected")
                
            elif connected:
                get_ntp()
                await asyncio.sleep(1)
        
        # Print time on 30 min intervals
        if s in (1,) and not m % 30:
            try:
                record(f"datapoint @ {timestamp}")
                
                gc_text = f"free: {str(gc.mem_free())}\n"
                gc.collect()
            except Exception as e:
                with open(ERRORLOGFILENAME, 'a') as file:
                    file.write(f"error printing: {repr(e)}\n")

        # Once daily (during the wee hours)
        if h == 2 and m == 10 and s == 1:
            
            # Read lines from previous day
            with open(DATAFILENAME) as f:
                lines = f.readlines()

            # first line is yesterday's date
            yesterdate = lines[0].split()[-1].strip()

            # cull all lines containing '@'
            lines = [line
                     for line in lines
                     if '@' not in line]
            
            # Log lines from previous day
            with open(LOGFILENAME, 'a') as f:
                for line in lines:
                    f.write(line)
            
            # Start a new data file for today
            with open(DATAFILENAME, 'w') as file:
                file.write('Date: %d/%d/%d\n' % (mo, d, y))

    except Exception as e:
        with open(ERRORLOGFILENAME, 'a') as file:
            file.write(f"logging loop error: {str(e)}\n")



async def serve_client(reader, writer):
    
    
    try:
        print("Client connected")
        request_line = await reader.readline()
        print("Request:", request_line)
        
        # We are not interested in HTTP request headers, skip them
        while await reader.readline() != b"\r\n":
            pass

        version = f"MicroPython Version: {sys.version}"

        if '/log' in request_line.split()[1]:
            with open(LOGFILENAME) as file:
                data = file.read()
            heading = "Debug"
            print('log demanded')
        elif '/err' in request_line.split()[1]:
            with open(ERRORLOGFILENAME) as file:
                data = file.read()
            heading = "ERRORS"
        else:
            with open(DATAFILENAME) as file:
                data = file.read()
            heading = "Append '/log' or '/err' to URL to see log file or error log"

        data += gc_text

        response = html % (heading, version, data)
        writer.write('HTTP/1.0 200 OK\r\nContent-type: text/html\r\n\r\n')
        writer.write(response)

        await writer.drain()
        await writer.wait_closed()
        print("Client disconnected")
    except Exception as e:
        with open(ERRORLOGFILENAME, 'a') as file:
            
            file.write(f"serve_client error @ {timestamp}: {str(e)}\n")


def record(line):
    """Combined print and append to data file."""
    print(line)
    line += '\n'
    with open(DATAFILENAME, 'a') as file:
        file.write(line)

def dprint(*args):
        logger.debug(*args)


# Demonstrate scheduler is operational.
async def heartbeat():
    s = True
    while True:
        await asyncio.sleep_ms(500)
        LED(s)
        s = not s

async def wifi_han(state):
    global connected
    s = "rssi: {}dB"
    LED(not state)
    if state:
        connected = True
        dprint('Wifi is up')
        dprint(s.format(rssi))
    else:
        dprint('Wifi is down')
        connected = False
    await asyncio.sleep(1)

async def get_rssi():
    global rssi
    s = network.WLAN()
    ssid = config["ssid"].encode("UTF8")
    #while True:
    try:
        while True:
            
            rssi = [x[3] for x in s.scan() if x[0] == ssid][0]
            
            break
        
    except IndexError:  # ssid not found.
        rssi = -199
        with open(ERRORLOGFILENAME, 'a') as file:
            file.write(f"ssid not found: {str(e)}\n")
            
    await asyncio.sleep(30)

async def get_ntp():
    
    try:
    
        settime()
        rtc = machine.RTC()
        utc_shift = 1

        tm = time.localtime(time.mktime(time.localtime()) + utc_shift*3600)
        tm = tm[0:3] + (0,) + tm[3:6] + (0,)
        rtc.datetime(tm)
            
    except OSError as e:
        with open(ERRORLOGFILENAME, 'a') as file:
            file.write(f"OSError while trying to set time: {str(e)}\n")        
        
    print("machine time is:",(time.localtime()))

# If you connect with clean_session True, must re-subscribe (MQTT spec 3.1.2.4)
async def conn_han(client):
    await client.subscribe(SUBSCRIBE_TOPIC1, qos=1)
    await client.subscribe(SUBSCRIBE_TOPIC2, qos=1)
    await client.subscribe(SUBSCRIBE_TOPIC3, qos=1)

# Subscription callback
def sub_cb(topic, msg, retained):
    
    global pos
    global raining
    global setangle
    
    dprint(f'Topic: "{topic.decode()}" Message: "{msg.decode()}" Retained: {retained}')
    
    if topic.decode() == SUBSCRIBE_TOPIC1:
                
        if not 0 <= int(msg.decode()) <= 36000:
            #dprint(str(msg.decode() + " is no INT"))
            setangle = 0
        else:
            setangle = int(msg.decode())
            
    
    elif topic.decode() == SUBSCRIBE_TOPIC3:
        if not 'rain' in CLIENT_ID:
            if str(msg.decode()) != "Raining":
                raining = False
                
            elif str(msg.decode()) == "Raining":
                raining = True

#Inverse input
async def swap_io():
    
    global oldval
    global pos

    if 'rain' in CLIENT_ID:
        if not rain():
            pos = 0
            if oldval == 1 or oldval == 0:
                dprint('Raining')
                await client.publish(PUBLISH_TOPIC4, f"Raining", qos=1)
                oldval = 2
        
        elif rain():
            pos = setangle

            if oldval == 2 or oldval == 0:
                dprint('Ready')
                await client.publish(PUBLISH_TOPIC4, f"Ready", qos=1)
                oldval = 1
            
    elif not 'rain' in CLIENT_ID:
        if not raining:
            pos = setangle

            if oldval == 1 or oldval == 0:
                dprint('Not raining')
                oldval = 2
            
        elif raining:
            pos = 0
            if oldval == 2 or oldval == 0:
                dprint('Raining')
                oldval = 1

# Homing sequence
async def homing():
    
    global homingneeded

    while True:
        await asyncio.sleep(1)
        await client.publish(PUBLISH_TOPIC1, f"Homing", qos=1)
        dprint("Homing")
        
        #Crash recovery
        if endswitch() and not alarm():
            await client.publish(PUBLISH_TOPIC1, f"Crash detected, recovery started", qos=1)
            dprint("Crash detected, recovery started")
            LED(1)
            s1.speed(1000) #use low speed for the calibration
             
            disable(0)
            s1.free_run(1)
            now = time.time()
            delay = 10
            while endswitch.value() == 1 and not alarm(): #wait till the switch is triggered
                if time.time() > now + delay:
                    s1.stop()
                    dprint("Changing direction")
                    break
                await asyncio.sleep(1)
                pass
            
            
            s1.free_run(-1) 
            now = time.time()
            delay = 10
            while endswitch.value() == 1 and not alarm(): #wait till the switch is triggered
                if time.time() > now + delay:
                    s1.stop()
                    disable(1)
                    dprint("Recovery failed! Entered sleep until reboot")
                    await client.publish(PUBLISH_TOPIC1, f"Recovery failed! Entered sleep until reboot", qos=1)
                    await asyncio.sleep(5)
                    machine.lightsleep()
                await asyncio.sleep(1)
                pass
            await client.publish(PUBLISH_TOPIC1, f"Recovery successful, homing started", qos=1)
            print("Recovery successful, start homing")
            
#Homing            
        if not endswitch() and not alarm():
            LED(1)
            s1.speed(500) #use low speed for the calibration
            s1.free_run(-1) #move backwards
            disable(0)
            while endswitch.value() == 0 and not alarm(): #wait till the switch is triggered
                pass
        
            s1.stop() #stop as soon as the switch is triggered
            s1.overwrite_pos(0) #set position as 0 point
            s1.target(0) #set the target to the same value to avoid unwanted movement
            await client.publish(PUBLISH_TOPIC2, str(s1.get_pos()), qos=1)
            homingneeded = False
            s1.free_run(1) #move forwards

            now = time.time()
            delay = 3
            while endswitch.value() == 1 and not alarm(): #wait till the switch is triggered
                if time.time() > now + delay:
                    s1.stop()
                    disable(1)
                    dprint("Homing failed!")
                    await client.publish(PUBLISH_TOPIC1, f"Homing failed!", qos=1)
                    await asyncio.sleep(5)
                    machine.soft_reset()
                pass
        
            await asyncio.sleep(0.1)        
            s1.stop() #stop as soon as the switch is triggered
            s1.overwrite_pos(0) #set position as 0 point
            s1.target(0) #set the target to the same value to avoid unwanted movement
            s1.speed(1000) #return to default speed
            s1.track_target() #start stepper again
            disable(1)
            await client.publish(PUBLISH_TOPIC1, f"Homing successful", qos=1)
            dprint("Homing successful")
            
        if alarm():
            await client.publish(PUBLISH_TOPIC1, f"DRIVE ALARM", qos=1)
            s1.stop()
            disable(1)
            dprint("DRIVE ALARM")
            await homing(client)
        LED(0)
        await asyncio.sleep(1)
        break

# Standard operating sequence
async def motion():

    updatepos = False
    
    s = "rssi: {}dB"
    

    while True and not alarm():
        await asyncio.sleep(0.5)
        await swap_io()
        gc.collect()
        m = gc.mem_free()
                   
        if endswitch():
            s1.stop()
            disable(1)
                        
            if pos >= s1.get_pos():
                s1.free_run(-1)
                disable(0)
                now = time.time()
                delay = 3           
                while endswitch.value() == 1: #wait till the switch is triggered
                    if time.time() > now + delay:
                        dprint("Recovery failed")
                        await client.publish(PUBLISH_TOPIC1, f"Recovery failed!", qos=1)
                        s1.stop()
                        disable(1)
                        await asyncio.sleep(5)
                        sys.exit("Recovery failed!")
                    pass
                
            elif pos <= s1.get_pos():
                s1.free_run(1)
                disable(0)
                now = time.time()
                delay = 3           
                while endswitch.value() == 1: #wait till the switch is triggered
                    if time.time() > now + delay:
                        dprint("Recovery failed")
                        await client.publish(PUBLISH_TOPIC1, f"Recovery failed!", qos=1)
                        s1.stop()
                        disable(1)
                        await asyncio.sleep(5)
                        sys.exit("Recovery failed!")
                    pass
            await asyncio.sleep(0.5)
            s1.stop()
            
            await client.publish(PUBLISH_TOPIC1, f"Positioning error!", qos=1)
            dprint("Positioning error!")
            await asyncio.sleep(5)
            await homing(client)
            break
        
        elif s1.get_pos() != pos and not endswitch():
            disable(0)
            s1.target(pos)
            await client.publish(PUBLISH_TOPIC1, f"Moving from: " + str(s1.get_pos()) + " to "+ str(pos), qos=1)
            await client.publish(PUBLISH_TOPIC2, str(s1.get_pos()), qos=1)
            dprint("Moving from: " + str(s1.get_pos()) + " to "+ str(pos))
            await asyncio.sleep(0.5)
            updatepos = True
            
        elif s1.get_pos() == pos and not endswitch() and updatepos:
            disable(1)
            await client.publish(PUBLISH_TOPIC1, f"Ready", qos=1)
            await client.publish(PUBLISH_TOPIC2, str(s1.get_pos()), qos=1)
            dprint("Ready")
            dprint(s.format(rssi))
            await asyncio.sleep(0.5)
            updatepos = False
                
    while True and alarm():
        
            await client.publish(PUBLISH_TOPIC1, f"DRIVE ALARM", qos=1)
            s1.stop()
            disable(1)
            dprint("DRIVE ALARM")
            await homing(client)

async def OTA():
    
    # Check for OTA updates
    repo_name = "PergolaPicoOTA"
    branch = "refs/heads/main"
    firmware_url = f"https://github.com/MartiMan79/{repo_name}/{branch}/"
    ota_updater = OTAUpdater(firmware_url,
                             "main.py",
                             "ota.py",
                             "log.py",
                             "lib/ntptime.py",
                             "lib/logging/handlers.py",
                             "lib/logging/__init__.py",
                             "lib/stepper/__init__.py",
                             )
    ota_updater.download_and_install_update_if_available()     

async def main(client):

  
    try:
        await client.connect()
        await client.publish(PUBLISH_TOPIC3, f'Connected', qos=1)
        await client.publish(PUBLISH_TOPIC4, f'Ready', qos=1)

       
    except OSError:
        
        with open(ERRORLOGFILENAME, 'a') as file:
            file.write(f"Connection failed: {str(e)}\n")
        
        return
    
    
    await get_ntp()
    await OTA()
    dprint("Startup ready")

    while True and homingneeded == True:
        
        await homing()
        break
    
    while True:

        await motion()
        

# Define configuration
config['subs_cb'] = sub_cb
config['wifi_coro'] = wifi_han
config['connect_coro'] = conn_han
config['clean'] = True

if 'rain' in CLIENT_ID:
    config['will'] = (PUBLISH_TOPIC4, f'pico_w_pergola/rain_sensor lost connection', False, 0)
elif not 'rain' in CLIENT_ID:
    config['will'] = (PUBLISH_TOPIC4, f'pico_w_pergola/no_sensor lost connection', False, 0)

config['keepalive'] = 120


# Set up client
MQTTClient.DEBUG = False  # Optional
client = MQTTClient(config)

asyncio.create_task(heartbeat())
asyncio.create_task(get_rssi())
asyncio.create_task(log_handling())
asyncio.create_task(asyncio.start_server(serve_client, "0.0.0.0", 80))

try:
    asyncio.run(main(client))
    
finally:
    client.close()  # Prevent LmacRxBlk:1 errors
    asyncio.new_event_loop()