Memory leak when calling cron_next #28

TD-er · 2020-02-27T10:56:37Z

At this moment I really have no idea where it could be.

I have narrowed it down to calling the cron_next. The used cron_expr is every time the same.

I'm running this code on an ESP8266, using the esp8266/Arduino platform (2.6.3)

The amount the free heap decreases is depending on the expression complexity when calling cron_next.

For example

* * * * * * decreases the heap by 64 bytes.
*/2 * * * * * decreases the heap by 80 bytes.

Sometimes it is also decreased by 112 bytes.

Example of log output running the code below:

60613 : Info  : Cron: Free Heap Decreased: 80 (12920 -> 12840
61256 : Info  : Cron: Free Heap Decreased: 64 (12720 -> 12656
61258 : Info  : Cron: Free Heap Decreased: 64 (12656 -> 12592
61286 : Info  : EVENT: Cron#bla
62257 : Info  : Cron: Free Heap Decreased: 64 (12936 -> 12872
62271 : Info  : EVENT: Cron#bla
63260 : Info  : Cron: Free Heap Decreased: 64 (12872 -> 12808
63293 : Info  : EVENT: Cron#bla
64257 : Info  : Cron: Free Heap Decreased: 64 (12808 -> 12744
64270 : Info  : EVENT: Cron#bla
65281 : Info  : Cron: Free Heap Decreased: 64 (11272 -> 11208
66258 : Info  : Cron: Free Heap Decreased: 64 (12080 -> 12016
66671 : Info  : EVENT: Cron#bla
66771 : Info  : EVENT: Cron#bla
67258 : Info  : Cron: Free Heap Decreased: 64 (12672 -> 12608
67272 : Info  : EVENT: Cron#bla
68259 : Info  : Cron: Free Heap Decreased: 64 (12608 -> 12544
68272 : Info  : EVENT: Cron#bla
69258 : Info  : Cron: Free Heap Decreased: 64 (12544 -> 12480
69272 : Info  : EVENT: Cron#bla
70260 : Info  : Cron: Free Heap Decreased: 64 (12408 -> 12344
70787 : Info  : EVENT: Cron#bla
71256 : Info  : Cron: Free Heap Decreased: 64 (12072 -> 12008
71292 : Info  : EVENT: Cron#bla
72257 : Info  : Cron: Free Heap Decreased: 64 (12352 -> 12288
72287 : Info  : EVENT: Cron#bla
73257 : Info  : Cron: Free Heap Decreased: 64 (12288 -> 12224
73286 : Info  : EVENT: Cron#bla
74256 : Info  : Cron: Free Heap Decreased: 64 (12224 -> 12160
74287 : Info  : EVENT: Cron#bla
75282 : Info  : Cron: Free Heap Decreased: 64 (9896 -> 9832
76257 : Info  : Cron: Free Heap Decreased: 64 (10840 -> 10776
76489 : Info  : EVENT: Cron#bla
76790 : Info  : EVENT: Cron#bla
77257 : Info  : Cron: Free Heap Decreased: 64 (12032 -> 11968
77290 : Info  : EVENT: Cron#bla
78257 : Info  : Cron: Free Heap Decreased: 64 (12160 -> 12096
78291 : Info  : EVENT: Cron#bla
79257 : Info  : Cron: Free Heap Decreased: 64 (12096 -> 12032
79289 : Info  : EVENT: Cron#bla
80256 : Info  : Cron: Free Heap Decreased: 64 (11576 -> 11512
80490 : Info  : EVENT: Cron#bla
81256 : Info  : Cron: Free Heap Decreased: 64 (11624 -> 11560
81290 : Info  : EVENT: Cron#bla
82257 : Info  : Cron: Free Heap Decreased: 64 (11904 -> 11840
82290 : Info  : EVENT: Cron#bla
83256 : Info  : Cron: Free Heap Decreased: 64 (11840 -> 11776
83290 : Info  : EVENT: Cron#bla
84256 : Info  : Cron: Free Heap Decreased: 64 (11776 -> 11712
84290 : Info  : EVENT: Cron#bla
85259 : Info  : Cron: Free Heap Decreased: 64 (11344 -> 11280
86190 : Info  : EVENT: Cron#bla
86257 : Info  : Cron: Free Heap Decreased: 64 (11224 -> 11160
86290 : Info  : EVENT: Cron#bla
87257 : Info  : Cron: Free Heap Decreased: 64 (11584 -> 11520
87290 : Info  : EVENT: Cron#bla
88257 : Info  : Cron: Free Heap Decreased: 64 (11184 -> 11120
88290 : Info  : EVENT: Cron#bla
89257 : Info  : Cron: Free Heap Decreased: 64 (11456 -> 11392
89290 : Info  : EVENT: Cron#bla
90306 : Info  : Cron: Free Heap Decreased: 64 (10936 -> 10872
90490 : Info  : EVENT: Cron#bla
91257 : Info  : Cron: Free Heap Decreased: 64 (10984 -> 10920
91290 : Info  : EVENT: Cron#bla
92259 : Info  : Cron: Free Heap Decreased: 64 (11264 -> 11200
92291 : Info  : EVENT: Cron#bla
93259 : Info  : Cron: Free Heap Decreased: 64 (11200 -> 11136
93292 : Info  : EVENT: Cron#bla
94258 : Info  : Cron: Free Heap Decreased: 64 (11136 -> 11072
94291 : Info  : EVENT: Cron#bla
95257 : Info  : Cron: Free Heap Decreased: 64 (10704 -> 10640
96190 : Info  : EVENT: Cron#bla
96257 : Info  : Cron: Free Heap Decreased: 64 (10584 -> 10520
96290 : Info  : EVENT: Cron#bla
97257 : Info  : Cron: Free Heap Decreased: 64 (10944 -> 10880
97289 : Info  : EVENT: Cron#bla
98257 : Info  : Cron: Free Heap Decreased: 64 (10808 -> 10744
98290 : Info  : EVENT: Cron#bla
99257 : Info  : Cron: Free Heap Decreased: 64 (10544 -> 10480
99293 : Info  : EVENT: Cron#bla

The ESP node is running a lot more, so that's why it sometimes does show a slight increase in free memory.
But as can be seen in the code segment below, the sampled free memory is just wrapping the call to cron_next.

Part of my code calling the function and logging the heap decrease:

    int32_t freeHeapStart = ESP.getFreeHeap();

    time_t res = P081_data->get_cron_next(last);

    int32_t freeHeapEnd = ESP.getFreeHeap();

    if (freeHeapEnd < freeHeapStart) {
      String log = F("Cron: Free Heap Decreased: ");
      log += String(freeHeapStart - freeHeapEnd);
      log += F(" (");
      log += freeHeapStart;
      log += F(" -> ");
      log += freeHeapEnd;
      addLog(LOG_LEVEL_INFO, log);
    }

The object wrapper I made to keep the expression and the calls to this library all in one place:

struct P081_data_struct : public PluginTaskData_base {
  P081_data_struct(const String& expression)
  {
    const char *error;

    memset(&_expr, 0, sizeof(_expr));
    cron_parse_expr(expression.c_str(), &_expr, &error);

    if (!error) {
      _initialized = true;
    } else {
      _error = String(error);
    }
  }

  ~P081_data_struct() {}

  bool isInitialized() {
    return _initialized;
  }

  bool hasError(String& error) {
    if (_initialized) { return false; }
    error = _error;
    return true;
  }

  time_t get_cron_next(time_t date) {
    if (!_initialized) { return CRON_INVALID_INSTANT; }
    return cron_next((cron_expr *)&_expr, date);
  }

  time_t get_cron_prev(time_t date) {
    if (!_initialized) { return CRON_INVALID_INSTANT; }
    return cron_prev((cron_expr *)&_expr, date);
  }

private:

  String    _error;
  cron_expr _expr;
  bool      _initialized = false;
};

Like I said, I really have not a clue where this memory leak should come from. It could also be something specific to esp8266/Arduino or even that I'm doing things completely wrong.

The text was updated successfully, but these errors were encountered:

staticlibs · 2020-02-27T11:23:18Z

Hi, thanks for the report! Sorry, I don't have cycles to dig this (and also don't have ESP dev env), if you find the cause for this - I will happily accept a PR.

TD-er · 2020-02-27T12:22:13Z

Thanks for the notice.
Could you maybe still spare some cycles to see if I did something very obviously wrong in the code I posted here?

In the mean time I am testing against several esp8266/Arduino core lib versions, just to make sure it is happening in all versions and if not, whether it may be a bug in their code.

TD-er · 2020-02-27T15:51:15Z

Found the culprit, but no idea yet how to patch it.
If I define CRON_USE_LOCAL_TIME then there is no memory leak.

So it must be in this section:

ccronexpr/ccronexpr.c

Lines 106 to 124 in 2fa1646

    
           #elif defined(ESP8266) || defined(ESP_PLATFORM) 
        
               /* https://linux.die.net/man/3/timegm */ 
        
               /* http://www.catb.org/esr/time-programming/ */ 
        
               /* portable version of timegm() */ 
        
               time_t ret; 
        
               char *tz; 
        
               tz = getenv("TZ"); 
        
               if (tz) 
        
                   tz = strdup(tz); 
        
               setenv("TZ", "UTC+0", 1); 
        
               tzset(); 
        
               ret = mktime(tm); 
        
               if (tz) { 
        
                   setenv("TZ", tz, 1); 
        
                   free(tz); 
        
               } else 
        
                   unsetenv("TZ"); 
        
               tzset(); 
        
               return ret;

FedeBev · 2020-06-11T19:20:41Z

Hi there,

I guess the issue is with the function setenv in the piece of code @TD-er has just mentioned.
But the reason is really tricky, I guess here is well explained.

Furthermore, why is there this piece of code?

if (tz) 
         tz = strdup(tz);

strdup makes a copy of tz, I suppose this could be another leak.

What do you think?

staticlibs · 2020-06-12T18:20:14Z

M, I cannot see obvious flaws in this piece of code. It is obviously not a nice way to do timegm (it may be better to avoid setenv() if possible) - it came in with #24 . If there exists better way to do timegm on ESP - I will happily accept a PR.

On strdup() call - I think it is necessary, original tz value may be overwritten after setenv() call - it is valid only before setenv(). It also seems to be freed unconditionally (except the same check as for strdup()), so doesn't look like a leak.

mdvorak · 2021-07-09T19:55:04Z

I'd like to point you to espressif/esp-idf#3046 - might be actual cause.

But also beware: I'm not sure how temporarily changing TZ on dual-core ESP32 will behave. It might return invalid values, or even crash... Or work without problems. I did not dig so deep yet. But generally calling setenv after program init is always dangerous. Finding better way would be great, but I don't know about any.

ghseb · 2021-07-23T06:49:17Z

Hello there,

we got a similar issue.

Heap is filled with strings like:

0x2004B930  553D5A54 302B4354 2004C300 2004C3AD 00000018 00000011 553D5A54 302B4354  TZ=UTC+0.Ã. Ã. ........TZ=UTC+0
0x2004B950  00000000 00000019 553D5A54 302B4354 2004C300 2004C315 00000018 00000011  ........TZ=UTC+0.Ã. .Ã. ........
0x2004B970  553D5A54 302B4354 3E333000 00000011 553D5A54 302B4354 3E384600 00000011  TZ=UTC+0.03>....TZ=UTC+0.F8>....
0x2004B990  553D5A54 302B4354 3E353100 00000011 553D5A54 302B4354 3E463100 00000011  TZ=UTC+0.15>....TZ=UTC+0.1F>....
0x2004B9B0  553D5A54 302B4354 3E333000 00000011 553D5A54 302B4354 3E373100 00000011  TZ=UTC+0.03>....TZ=UTC+0.17>....
0x2004B9D0  553D5A54 302B4354 3E443200 00000019 553D5A54 302B4354 334A6500 78744874  TZ=UTC+0.2D>....TZ=UTC+0.eJ3tHtx
0x2004B9F0  00000018 00000011 553D5A54 302B4354 FFFFFF00 00000011 553D5A54 302B4354  ........TZ=UTC+0.ÿÿÿ....TZ=UTC+0
0x2004BA10  322E3500 00000011 553D5A54 302B4354 81F9FD00 00000019 553D5A54 302B4354  .5.2....TZ=UTC+0.ýù.....TZ=UTC+0

Until now there is no proof that those strings are still allocated, but due to the out of memory hard faults it seems likely.

I could not spot an obvious flaw in the timegm implementation. The usage of strdup is suspicious (in contrast to the example shown at https://linux.die.net/man/3/timegm), but the allocated string is freed afterwards.

Edit:
I should add that this was observed on an STM32 using mbed-os and Arm GCC.

mdvorak · 2021-07-23T07:48:11Z

Hi, I don't know about STM32 libraries, but cause might be the same: leak is not caused by timegm or strdup, but by setenv.
If you can, use local time for cron, and this problem will not appear (problematic code won't be used).

ghseb · 2021-07-23T07:53:43Z

Hello,
i investigated the issue a bit. It turned out that in my case the TZ environment variable was not set initially. This causes the variable to be toggling between UTC+0 and being unset (unsetenv("TZ")). Eventually this is an variant of the bug that was described here: https://lists.freebsd.org/pipermail/freebsd-bugs/2006-July/019280.html

It seems that setting the TZ variable initially to some value (e.g. UTC+0) is another workaround for the issue:

setenv("TZ", "UTC+0", 1);
tzset();

Gero-Raven · 2023-02-25T15:26:46Z

Hello,

"cron next" calls "cron mktime" twice, which in turn calls "cron mktime gm". The time zone is obviously set with each call with "getenv" and "setenv". I don't think this is nice, because according to my understanding, something like this is an initialization that belongs once at the beginning of a program. However, this part leads to the memory leak observed here. If the setting of the time zone is commented out (see below), "cron next" works without any disadvantages that I can see and without a memory leak!

staticlibs · 2023-09-10T12:17:56Z

This project is no longer maintained, see its updated and extended fork in exander77/supertinycron repo, closing the issue to archive the repo.

TD-er mentioned this issue Feb 27, 2020

[Cron] P081_cron has a memory leak letscontrolit/ESPEasy#2907

Closed

staticlibs closed this as completed Sep 10, 2023

TD-er mentioned this issue Sep 10, 2023

[Cron] Fix unintended month rollovers, ported from staticlibs#35 letscontrolit/ESPEasy#4406

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Memory leak when calling cron_next #28

Memory leak when calling cron_next #28

TD-er commented Feb 27, 2020

staticlibs commented Feb 27, 2020

TD-er commented Feb 27, 2020

TD-er commented Feb 27, 2020

FedeBev commented Jun 11, 2020 •

edited

Loading

staticlibs commented Jun 12, 2020

mdvorak commented Jul 9, 2021

ghseb commented Jul 23, 2021 •

edited

Loading

mdvorak commented Jul 23, 2021

ghseb commented Jul 23, 2021

Gero-Raven commented Feb 25, 2023

staticlibs commented Sep 10, 2023

Memory leak when calling cron_next #28

Memory leak when calling cron_next #28

Comments

TD-er commented Feb 27, 2020

staticlibs commented Feb 27, 2020

TD-er commented Feb 27, 2020

TD-er commented Feb 27, 2020

FedeBev commented Jun 11, 2020 • edited Loading

staticlibs commented Jun 12, 2020

mdvorak commented Jul 9, 2021

ghseb commented Jul 23, 2021 • edited Loading

mdvorak commented Jul 23, 2021

ghseb commented Jul 23, 2021

Gero-Raven commented Feb 25, 2023

staticlibs commented Sep 10, 2023

FedeBev commented Jun 11, 2020 •

edited

Loading

ghseb commented Jul 23, 2021 •

edited

Loading