Firmware release 1.7.1.b1

this.wiederkehr

There are multiple issues with this release:

1. RTC time sync with ntp is not working correctly anymore with this release:

(sysname='LoPy', nodename='LoPy', release='1.7.1.b2', version='v1.8.6-642-g84447452 on 2017-06-03', machine='LoPy with ESP32', lorawan='1.0.0')

With the 1.6.XX I could easily sync with ntp server, e.g. rtc.ntp_sync("pool.ntp.org"). Some time after this call rtc.now() would return the current time. Now this is not happening any more time does not get synced at all even after minutes. No Idea why. There is also no way to know what is wrong...

2. Guru Mediation Error Load Prohibited

After a few minutes of running my app I get around 30 of the following exceptions with different backtrace and the board resets:

Guru Meditation Error of type LoadProhibited occurred on core  0. Exception was unhandled.
Register dump:
PC      : 0x400875b9  PS      : 0x00060033  A0      : 0x40088c47  A1      : 0x3ffbd5d0  
A2      : 0x00050023  A3      : 0x00000000  A4      : 0x00000001  A5      : 0x3ffc3dc8  
A6      : 0x000ee81c  A7      : 0x3ffc0df4  A8      : 0x00000005  A9      : 0x00000001  
A10     : 0x3ffc3e34  A11     : 0x00000000  A12     : 0x3ffc3e34  A13     : 0x00000000  
A14     : 0x00000000  A15     : 0x00000000  SAR     : 0x00000016  EXCCAUSE: 0x0000001c  
EXCVADDR: 0x00000048  LBEG    : 0x4000c2e0  LEND    : 0x4000c2f6  LCOUNT  : 0xffffffff  

Backtrace: 0x400875b9:0x3ffbd5d0 0x40088c47:0x3ffbd5f0 0x40088c01:0x3ffbd630 0x4013d1d7:0x000ee81c

3. Freeze The title says it all and I cant add any more information as on freeze it does not provide any more information ....

Please, please, please get out something which is stable!!! Right now this is not usable for anything more than doing TESTS!

daniel

@this-wiederkehr thanks for your post. I'm sorry about your frustration. We only release new software when all our automatic tests (more than 400) are passing. I'll check asap what's happening with the NTP sync and fix it, but if you can provide a minimal example to reproduce the crash I will appreciate it very much.

Thanks again.

Cheers,
Daniel

this.wiederkehr

@daniel indeed this is frustrating.. Thanks for showing interest in solving the issues:

Issue1: NTP SYNC

This is straight forward:

import utime

from machine import RTC
from network import WLAN

wl = WLAN()
wl.mode(WLAN.STA)

wl.connect('XX', auth=(X, 'XX'))



rtc = RTC()
rtc.init()
rtc.ntp_sync('pool.ntp.ort')

while True:
    print(rtc.now())
    print(wl.isconnected())
    utime.sleep_ms(1000)

What it does: Prints time tuple but stays in year 1970. :

(1970, 1, 1, 0, 25, 56, 158744, None)
True
...

I also saw examples where it jumped to a year far in the future: (62236, 1, 19, 7, 16, 53, 555967, None)
While on it: It would be great if the api for the rtc could be extended in order to know if a sync took place. something like last_synced which should return the time elapsed since the last sync or none if a sync never succeeded.

Actually it is not as easy for the second and third issue to provide a minimal example as the issue does not happen each time the same code path runs but arbitrarily, read on...

Something about my setup:

I'm using the expansion board with an sd-card populated
I'm using P10, P11 and P12 for spi communication and additionally P9 for CS (chip select) attached is an acceleration sensor with a fifo buffer
Several times a second I read the data from the fifo through spi and dump it to the a file on the sd card and call flush to persist the changes in a file.
Issue 2 and 3 both happen around flushing the write to the sd-card, either just during flushing or nearly after, however they do not happen each time! The app runs for as little as a few seconds before issue 2 or 3 occur or as long as about 20 minutes. However I did not see much longer durations.

dummy code:

f = open(file_on_sd, 'a')
f.write(data)
print('about to flush')
f.flush() # <-- Both issues are located here or right after that call
print('flushed') # <-- Sometimes even this line is printed and freeze occurs afterward

Issue 3: Freeze on sd flush
Issue 3 occurs during or right after flushing
I read the issue https://github.com/espressif/esp-idf/issues/569 which is about a race condition on reused pins for sd-card and something else. So I thought that the freeze is related to this and I probably should not use P9 for CS of the SPI device. Switching from P9 to P14 for CS seemes to solve the problem with freezing, still this seems like a workaround which should not be required in the first place.

While playing I found how you can make the interpreter freeze reproducible at that line, though this might be totally different issue or even expected:

import machine
import os

sd = machine.SD()
os.mount(sd, '/sd')

f = open('/sd/test', 'a')

while True:
    f.write('blabla')
    print('about to disable irq')
    machine.disable_irq()
    print('about to flush to file')
    f.flush() # <-- freezes reproducible at that call
    print('about to enable irq')
    machine.enable_irq()
    print("I'm done")

Issue 2: Load prohibited
Occurrence of this error is at the same location as the the freeze issue, however I did not have time to dig into it. It might be easier for you anyway by using the stack trace.

I also noticed freezes during gc collect but these seems quite rare.

livius

@this.wiederkehr said in Firmware release 1.7.1.b1:

pool.ntp.ort

is this sample or you have really this wrong address? ort but should be org

this.wiederkehr

@livius thanks for pointing out that typo! Even with the correct address the behavior is the same. Does ntp_sync work for you with this firmware?

daniel

@this-wiederkehr thanks for the extra details. We have found the issue with ntp_sync and it's being fixed. We will also add the method to query when that last sync occurred. Using your input we are also investigating the crash and freeze.

Cheers,
Daniel

daniel

@this-wiederkehr something I don't understand. P9 is not used by the SD card, it's P8. Also P14 is an input only pin, so how is that possible that you can use it to act as chip select?

Cheers,
Daniel

Strevens

@daniel Thanks for the prompt action on the NTP sync. looking forward to the new build.

could you clarify where the firmware versions are archived as the link on the web says page not found when following the link on quick start page.

https://www.pycom.io/support/supportdownloads/#firmware

daniel

@Strevens the updater tool is located here: https://www.pycom.io/downloads/

You can use the following link to the the latest release:

https://software.pycom.io/downloads/LoPy_868-1.7.1.b2.tar.gz

If you want a different version, just replace the version number/name on the link accordingly.

Cheers,
Daniel

this.wiederkehr

@daniel Thanks for the update and great you found the issue with ntp_sync.

P9 on the Lopy is labeld SD_DATA2 that is why I thought it might somehow be involved. I know it is not connected on the expansion board.

Sorry about P14 should read Pin 14, GPIO25 or P22.

I have a test going on and will report back if changeing the CS pin to that pin solved the issue with the freeze.

Strevens

@daniel Thanks!

this.wiederkehr

@daniel Analyzing the output of today I see tree different stack traces.

At least once I still got a freeze even with the CS pin switched to P22. I have the subjective feeling that freezing occurs less frequently with the CS pin on P22 rather than P9 but that could be just my imagination.

sometimes I see strange behavior, that when the python interpreter freezes I can advance it by updating in the ftp window. So it looks like an ftp request to the lopy does advance the python interpreter...
I do observe this by looking at the serial output which shows debug messages of my app.

So the following is about issue 2 which indeed seem to be another 3 different issues as I get 3 different stack traces.
All the following errors occur near flushing data to the sd-card

Guru Meditation Error of type LoadProhibited occurred on core  0. Exception was unhandled.
Register dump:
PC      : 0x400875b9  PS      : 0x00060033  A0      : 0x40088c47  A1      : 0x3ffbd5d0  
A2      : 0x00050023  A3      : 0x00000000  A4      : 0x00000001  A5      : 0x3ffc3dc8  
A6      : 0x000ee81c  A7      : 0x3ffc0df4  A8      : 0x00000005  A9      : 0x00000001  
A10     : 0x3ffc3e34  A11     : 0x00000000  A12     : 0x3ffc3e34  A13     : 0x00000000  
A14     : 0x00000000  A15     : 0x00000000  SAR     : 0x00000016  EXCCAUSE: 0x0000001c  
EXCVADDR: 0x00000048  LBEG    : 0x4000c2e0  LEND    : 0x4000c2f6  LCOUNT  : 0xffffffff  

Backtrace: 0x400875b9:0x3ffbd5d0 0x40088c47:0x3ffbd5f0 0x40088c01:0x3ffbd630 0x4013d1d7:0x000ee81c

0x400875b9: vTaskSwitchContext at /Users/danicampora/Code/Espressif/IDF/esp-idf-20170527/components/freertos/./tasks.c:4873
0x40088c47: _frxt_dispatch at ??:?
0x40088c01: _frxt_int_exit at ??:?
0x4013d1d7: lwip_accept_r at /Users/danicampora/Code/Espressif/IDF/esp-idf-20170527/components/lwip/api/sockets.c:3235

Guru Meditation Error of type LoadProhibited occurred on core  0. Exception was unhandled.
Register dump:
PC      : 0x40087eb9  PS      : 0x00060031  A0      : 0x80086722  A1      : 0x3ffc07b0  
A2      : 0x00000001  A3      : 0x00000001  A4      : 0x000d6f4f  A5      : 0x00000006  
A6      : 0x000002aa  A7      : 0x3ffc5fa0  A8      : 0x3ffc3fbc  A9      : 0x3ffc0790  
A10     : 0x3ffc3e40  A11     : 0x00000001  A12     : 0x00000004  A13     : 0x00000000  
A14     : 0x000000aa  A15     : 0x3ffc5f00  SAR     : 0x00000016  EXCCAUSE: 0x0000001c  
EXCVADDR: 0x00000009  LBEG    : 0x400f3178  LEND    : 0x400f3180  LCOUNT  : 0x00000000  

Backtrace: 0x40087eb9:0x3ffc07b0 0x40086722:0x3ffc07d0 0x40088c1c:0x3ffc07f0 0x40081861:0x3ffc0800

0x40087eb9: xTaskIncrementTick at /Users/danicampora/Code/Espressif/IDF/esp-idf-20170527/components/freertos/./tasks.c:4873
0x40086722: xPortSysTickHandler at /Users/danicampora/Code/Espressif/IDF/esp-idf-20170527/components/freertos/./port.c:420
0x40088c1c: _frxt_timer_int at ??:?
0x40081861: _xt_lowint1 at xtensa_vectors.o:?


Guru Meditation Error of type LoadProhibited occurred on core  0. Exception was unhandled.
Register dump:
PC      : 0x40148aec  PS      : 0x00060a30  A0      : 0x8013d9d4  A1      : 0x3ffc5ce0  
A2      : 0x4013d894  A3      : 0x00000000  A4      : 0x00000001  A5      : 0x3ffc5e88  
A6      : 0x3ffc5d50  A7      : 0x00000d5e  A8      : 0x3ffb483c  A9      : 0x3fff8b50  
A10     : 0x00000002  A11     : 0x00000004  A12     : 0x3ffc6a40  A13     : 0x3ffc5e60  
A14     : 0x00000002  A15     : 0x3ffc5e40  SAR     : 0x00000020  EXCCAUSE: 0x0000001c  
EXCVADDR: 0x0000000a  LBEG    : 0x400f7ae2  LEND    : 0x400f7aeb  LCOUNT  : 0x00000000  

0x40148aec: sys_untimeout at /Users/danicampora/Code/Espressif/IDF/esp-idf-20170527/components/lwip/core/timers.c:429
0x4013d9d4: sntp_stop at /Users/danicampora/Code/Espressif/IDF/esp-idf-20170527/components/lwip/apps/sntp/sntp.c:681
0x400dd879: mach_rtc_ntp_sync at /builds/this-wiederkehr/pycom-micropython-sigfox/esp32/mods/machrtc.c:55
0x400ef371: fun_builtin_var_call at /builds/this-wiederkehr/pycom-micropython-sigfox/esp32/../py/objfun.c:124
0x400eb850: mp_call_function_n_kw at /builds/this-wiederkehr/pycom-micropython-sigfox/esp32/../py/runtime.c:562
0x400eb8b8: mp_call_method_n_kw at /builds/this-wiederkehr/pycom-micropython-sigfox/esp32/../py/runtime.c:591
0x400f7430: mp_execute_bytecode at /builds/this-wiederkehr/pycom-micropython-sigfox/esp32/../py/vm.c:980
0x400ef303: fun_bc_call at /builds/this-wiederkehr/pycom-micropython-sigfox/esp32/../py/objfun.c:276
0x400eb850: mp_call_function_n_kw at /builds/this-wiederkehr/pycom-micropython-sigfox/esp32/../py/runtime.c:562
0x400eb8b8: mp_call_method_n_kw at /builds/this-wiederkehr/pycom-micropython-sigfox/esp32/../py/runtime.c:591
0x400f7430: mp_execute_bytecode at /builds/this-wiederkehr/pycom-micropython-sigfox/esp32/../py/vm.c:980
0x400ef303: fun_bc_call at /builds/this-wiederkehr/pycom-micropython-sigfox/esp32/../py/objfun.c:276
0x400eb850: mp_call_function_n_kw at /builds/this-wiederkehr/pycom-micropython-sigfox/esp32/../py/runtime.c:562
0x400eb87d: mp_call_function_0 at /builds/this-wiederkehr/pycom-micropython-sigfox/esp32/../py/runtime.c:562
0x400d9166: parse_compile_execute at /builds/this-wiederkehr/pycom-micropython-sigfox/esp32/../lib/utils/pyexec.c:534
0x400d9435: pyexec_file at /builds/this-wiederkehr/pycom-micropython-sigfox/esp32/../lib/utils/pyexec.c:505
0x400d841c: TASK_Micropython at /builds/this-wiederkehr/pycom-micropython-sigfox/esp32/mptask.c:245

I'll now stop the ntp_sync, ftp and telnet server and see if the app is still going to crash or freeze.

I also noticed that core dump is not working anymore this leads to multiple exceptions raised in a row all related to the not working core dump. I think this used to work in earlier versions ...

Innocenzo

@daniel Hi, also the repository on github is updated to 1.7.1.b2?
I've cloned the new pycom-micropython-sigfox repository and the new pycom-esp-idf repository, but the firmware generated make my wipy board in a fault state (RED led permanently on).

I must use this procedure in order to create a wipy firmware with some frozen module!

daniel

@Innocenzo please try erasing your flash memory first as there were changes in the partitions table. Another option is to flash the firmware via the updater tool and then flashing with your own built firmware.

Innocenzo

@daniel what is the command to erase the flash memory?

Anyway I've update the wipy to 1.7.1.b2 using the updater tool and then I try to update my own firmware but the result doesn't change. Red Led ON.

daniel

@Innocenzo have you rebuilt the bootloader? The command is erase instead of flash

robert-hh

@Innocenzo I had the same trouble (see my posts below): After using the updater tool once, you have to erase the flash BEFORE you use you load youe own-built firmware. You can do that with:

make erase

HOWEVER, after doing that, the board does not run boot.py or main.py any more. It considers itself in the safeboot mode. This is a software fault.
I'm interested if that happes to you too? If yes, you could still call boot.py and main.py from frozen/_boot.py, which is called always.

Innocenzo

@daniel said in Firmware release 1.7.1.b1:

@Innocenzo have you rebuilt the bootloader? The command is erase instead of flash

yes.

I have erased the old repository ;
I have downloaded the new pycom-micropython-sigfox and pycom-esp-idf;
git submodule update --init in all repository
in pycom-micropython-sigfox/mpy-cross make all
in pycom-micropython-sigfox/esp32:
make BOARD=WIPY TARGET=boot;
make BOARD=WIPY TARGET=app;
make BOARD=WIPY flash.

Innocenzo

@robert-hh Yes. The boot.py and the main.py present in /flash/ dir, do not start after flashing my own firmware.

robert-hh

@Innocenzo Before the step:
make BOARD=WIPY flash
you have to do:
make BOARD=WIPY erase
In order to erase the flash memory on the device. Obviously, all content on the device will be lost!

Explore Pybytes | Official Documentation | Report a Firmware Bug/Issue | GitHub

Firmware release 1.7.1.b1

Pycom on Twitter