1638271386.toit-sim-4786.hardware_id-4c2a0869-49c3-4fe7-834e-ce3a6a9e2b7c.firmware-v1.6.0-pre.33+3fba4aea7.log

$ toit serial reinstall --firmware v1.6.0-pre.33+3fba4aea7 -p model.cellular.enabled=1 -p model.cellular.tx=5 -p model.cellular.rx=23 -p model.cellular.rts=19 -p model.cellular.cts=18 -p model.cellular.pwr=27 -p model.cellular.monarch=1 -p cellular.apn=nbiot.tdc.dk --port=/dev/ttyUSB0 --debug
Detecting chip type. This can take up to 10s.
Reinstalling hardware with firmware: v1.6.0-pre.33+3fba4aea7 (using model: esp32-4mb) on port /dev/ttyUSB0
Running "/home/christian/.cache/toit/tools/esptool_linux_v3.0 --chip esp32 --port /dev/ttyUSB0 --baud 921600 --before default_reset --after hard_reset write_flash -z --flash_mode dio --flash_freq 40m --flash_size detect 0xd000 /tmp/092705268/otadata413179075 0x10000 /tmp/092705268/ota_0390544710"
esptool.py v3.0
Serial port /dev/ttyUSB0
Connecting.......
Chip is ESP32-D0WDQ6 (revision 1)
Features: WiFi, BT, Dual Core, 240MHz, VRef calibration in efuse, Coding Scheme None
Crystal is 40MHz
MAC: f0:08:d1:ce:c3:b0
Uploading stub...
Running stub...
Stub running...
Changing baud rate to 921600
Changed.
Configuring flash size...
Auto-detected Flash size: 8MB
Compressed 8192 bytes to 31...
Writing at 0x0000d000... (100 %)
Wrote 8192 bytes (31 compressed) at 0x0000d000 in 0.0 seconds (effective 23342.2 kbit/s)...
Hash of data verified.
Compressed 1327712 bytes to 804990...
Writing at 0x00010000... (2 %)
Writing at 0x00014000... (4 %)
Writing at 0x00018000... (6 %)
Writing at 0x0001c000... (8 %)
Writing at 0x00020000... (10 %)
Writing at 0x00024000... (12 %)
Writing at 0x00028000... (14 %)
Writing at 0x0002c000... (16 %)
Writing at 0x00030000... (18 %)
Writing at 0x00034000... (20 %)
Writing at 0x00038000... (22 %)
Writing at 0x0003c000... (24 %)
Writing at 0x00040000... (26 %)
Writing at 0x00044000... (28 %)
Writing at 0x00048000... (30 %)
Writing at 0x0004c000... (32 %)
Writing at 0x00050000... (34 %)
Writing at 0x00054000... (36 %)
Writing at 0x00058000... (38 %)
Writing at 0x0005c000... (40 %)
Writing at 0x00060000... (42 %)
Writing at 0x00064000... (44 %)
Writing at 0x00068000... (46 %)
Writing at 0x0006c000... (48 %)
Writing at 0x00070000... (50 %)
Writing at 0x00074000... (52 %)
Writing at 0x00078000... (54 %)
Writing at 0x0007c000... (56 %)
Writing at 0x00080000... (58 %)
Writing at 0x00084000... (60 %)
Writing at 0x00088000... (62 %)
Writing at 0x0008c000... (64 %)
Writing at 0x00090000... (66 %)
Writing at 0x00094000... (68 %)
Writing at 0x00098000... (70 %)
Writing at 0x0009c000... (72 %)
Writing at 0x000a0000... (74 %)
Writing at 0x000a4000... (76 %)
Writing at 0x000a8000... (78 %)
Writing at 0x000ac000... (80 %)
Writing at 0x000b0000... (82 %)
Writing at 0x000b4000... (84 %)
Writing at 0x000b8000... (86 %)
Writing at 0x000bc000... (88 %)
Writing at 0x000c0000... (90 %)
Writing at 0x000c4000... (92 %)
Writing at 0x000c8000... (94 %)
Writing at 0x000cc000... (96 %)
Writing at 0x000d0000... (98 %)
Writing at 0x000d4000... (100 %)
Wrote 1327712 bytes (804990 compressed) at 0x00010000 in 13.1 seconds (effective 810.7 kbit/s)...
Hash of data verified.

Leaving...
Hard resetting via RTS pin...
Hardware successfully reinstalled with the Toit firmware.
The hardware has been reinstalled with the following configurations:
+------------------------+----------------+
|        SETTING         |     VALUE      |
+------------------------+----------------+
| context                | remote         |
| broker.host            | device.toit.io |
| model.cellular.rts     | 19             |
| cellular.apn           | nbiot.tdc.dk   |
| model                  | esp32-4mb      |
| model.cellular.rx      | 23             |
| broker.cn              | device.toit.io |
| broker.port            | 9426           |
| model.cellular.cts     | 18             |
| model.cellular.pwr     | 27             |
| model.cellular.monarch | 1              |
| model.cellular.enabled | 1              |
| model.cellular.tx      | 5              |
+------------------------+----------------+


$ toit serial info --output table
+-------------------------------------------------------------------------+-----------+--------------------------------------+
|                                  NAME                                   |   MODEL   |             HARDWARE ID              |
+-------------------------------------------------------------------------+-----------+--------------------------------------+
| 4c2a0869-49c3-4fe7-834e-ce3a6a9e2b7c.744.2021-09-26.device.toitware.com | esp32-4mb | 4c2a0869-49c3-4fe7-834e-ce3a6a9e2b7c |
+-------------------------------------------------------------------------+-----------+--------------------------------------+


$ toit serial monitor
ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0030,len:188
ho 0 tail 12 room 4
load:0x40078000,len:12180
load:0x40080400,len:2944
entry 0x400805c8
clearing RTC memory: RTC memory is in inconsistent state
[flash reg] address 0x3f46c000, size 0x00134000
[IDENTITY] name=4c2a0869-49c3-4fe7-834e-ce3a6a9e2b7c.744.2021-09-26.device.toitware.com,model=esp32-4mb
(0.015825) [toit] INFO: booting toit {sdk: v1.6.0-pre.33+3fba4aea7, model: esp32-4mb}
(0.021974) [toit.scheduler] INFO: set initial run_level {run_level: 4}
(0.415452) [toit.state] INFO: starting new session {session_id: 1, session_time: 0.422459}
[gc @ 0x3ffcf9f0* | soft limit reached (20480 >= 18432)]
[gc @ 0x3ffcf9f0* | heap: 20kb -> 8kb | external: 0kb -> 0kb | used: 94kb | free: 9kb->149kb (largest 108kb) 3.174ms]
(0.507782) [toit.kernel] INFO: using model parameters {cellular.cts: 18, cellular.enabled: 1, cellular.monarch: 1, cellular.pwr: 27, cellular.rts: 19, cellular.rx: 23, cellular.tx: 5}
(0.618007) [toit.console_sync] INFO: loaded last console sync {time: null}
(0.630203) [toit.scheduler] INFO: running job {job: console_sync}
(0.632835) [toit.scheduler] INFO: running job {job: flush_metrics}
(0.634741) [toit.scheduler] INFO: running job {job: poll_metric_flash_usage}
[gc @ 0x3ffcf9f0* | soft limit reached (24576 >= 24576)]
[gc @ 0x3ffcf9f0* | byte array allocation failed, length = 6 (heap)]
[gc @ 0x3ffcf9f0* | heap: 24kb -> 16kb | external: 0kb -> 0kb | used: 102kb | free: 12kb->140kb (largest 108kb) 5.205ms]
(0.639918) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(0.671586) [toit.console] INFO: waiting for console connection to be established
(0.675993) [toit.network] DEBUG: connecting {network: Cellular (nbiot.tdc.dk)}
(0.683758) [toit.metrics] INFO: persisting metrics
(0.686799) [toit.metrics] INFO: flushing metrics
[gc @ 0x3ffcf9f0* | soft limit reached (36892 >= 36864)]
[gc @ 0x3ffcf9f0* | byte array allocation failed, length = 511 (heap)]
[gc @ 0x3ffcf9f0* | heap: 36kb -> 20kb | external: 0kb -> 0kb | used: 127kb | free: 12kb->116kb (largest 104kb) 5.675ms]
(0.893568) [toit] INFO: -> AT
(0.906203) [toit] INFO: <- OK
(1.010682) [toit] INFO: -> ATE0
(1.016480) [toit] INFO: <- OK
(1.039166) [toit] INFO: -> AT+CMEE=2
(1.044671) [toit] INFO: <- OK
[gc @ 0x3ffcf9f0* | soft limit reached (45084 >= 43050)]
[gc @ 0x3ffcf9f0* | byte array allocation failed, length = 511 (heap)]
[gc @ 0x3ffcf9f0* | heap: 44kb -> 24kb | external: 0kb -> 0kb | used: 149kb | free: 6kb->94kb (largest 88kb) 6.350ms]
(1.067094) [toit] INFO: -> AT+CGMM
(1.072903) [toit] INFO: <- FiPy
(1.075855) [toit] INFO: <- OK
(1.097904) [toit] INFO: -> AT+CGMR
(1.103011) [toit] INFO: <- UE5.4.0.2
(1.105630) [toit] INFO: <- OK
(1.127648) [toit] INFO: -> AT+SQNCCID?
(1.133765) [toit] INFO: <- +SQNCCID: "89882390000069114786",""
(1.136355) [toit] INFO: <- OK
(1.140988) [toit.cellular] DEBUG: initialized {model: FiPy, version: UE5.4.0.2, iccid: 89882390000069114786}
(1.160743) [toit] INFO: -> AT+CFUN=4
(2.063599) [toit] INFO: <- OK
(2.066586) [toit] INFO: <- +SQNSH: 1
(2.068877) [toit] INFO: <- [URC] +SQNSH [1]
(2.089065) [toit] INFO: -> AT+CPIN?
(2.095061) [toit] INFO: <- +CPIN: READY
(2.097588) [toit] INFO: <- OK
(2.119857) [toit] INFO: -> AT+CEREG=2
(2.142055) [toit] INFO: <- OK
(2.164545) [toit] INFO: -> AT+CPSMS=0
(2.171945) [toit] INFO: <- OK
(2.194489) [toit] INFO: -> AT+CEDRXS=0
(2.202134) [toit] INFO: <- OK
(2.224663) [toit] INFO: -> AT+SQNIBRCFG=0
(2.239333) [toit] INFO: <- OK
(2.262017) [toit] INFO: -> AT+SQNIPSCFG=1,100
(2.279711) [toit] INFO: <- OK
(2.302470) [toit] INFO: -> AT+SQNBANDSEL=0,"standard","20"
(2.375069) [toit] INFO: <- +SQNBANDSEL: <custom>
(2.377820) [toit] INFO: <- OK
(2.400257) [toit] INFO: -> AT+SQNBANDSEL=1,"standard","20"
(2.407479) [toit] INFO: <- +CME ERROR: operation not supported
(2.429634) [toit] INFO: -> AT+CGDCONT?
(2.435926) [toit] INFO: <- +CGDCONT: 1,"IP","nbiot.tdc.dk",,,,0,0,0,0,0,0,0,,0
(2.441237) [toit] INFO: <- OK
(2.463566) [toit] INFO: -> AT+CFUN=1
(2.539628) [toit] INFO: <- OK
(2.732546) [toit] INFO: <- +CEREG: 2
(2.734783) [toit] INFO: <- [URC] +CEREG [2]
(2.736940) [toit.cellular] DEBUG: attempt modem's automatic connect
(2.750795) [toit.cellular] DEBUG: connecting {operator: null, attempt: 1}
(2.755065) [toit] INFO: -> AT+COPS?
(2.762912) [toit] INFO: <- +COPS: 0
(2.765916) [toit] INFO: <- OK
(2.788237) [toit] INFO: -> AT+CEREG=2
(2.798801) [toit] INFO: <- OK
(2.821125) [toit] INFO: -> AT+CEREG?
(2.827016) [toit] INFO: <- +CEREG: 2,2
(2.829580) [toit] INFO: <- OK
(3.833878) [toit] INFO: -> AT
(3.845895) [toit] INFO: <- OK
(4.850524) [toit] INFO: -> AT
(4.855569) [toit] INFO: <- OK
(5.859959) [toit] INFO: -> AT
(5.865197) [toit] INFO: <- OK
(6.869889) [toit] INFO: -> AT
(6.875385) [toit] INFO: <- OK
(7.880338) [toit] INFO: -> AT
(7.885204) [toit] INFO: <- OK
(8.889630) [toit] INFO: -> AT
(8.894365) [toit] INFO: <- OK
(9.898939) [toit] INFO: -> AT
(9.904253) [toit] INFO: <- OK
[gc @ 0x3ffcf9f0* | soft limit reached (53276 >= 49194)]
[gc @ 0x3ffcf9f0* | string allocation failed, length = 6 (heap)]
[gc @ 0x3ffcf9f0* | heap: 52kb -> 24kb | external: 0kb -> 0kb | used: 165kb | free: 10kb->78kb (largest 68kb) 6.615ms]
(10.630733) [toit.scheduler] INFO: running job {job: persist_metrics}
(10.650085) [toit.metrics] INFO: persisting metrics
(10.895129) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(10.909192) [toit] INFO: -> AT
(10.915015) [toit] INFO: <- OK
(11.919656) [toit] INFO: -> AT
(11.924568) [toit] INFO: <- OK
(12.928875) [toit] INFO: -> AT
(12.933748) [toit] INFO: <- OK
(13.940572) [toit] INFO: -> AT
(13.945503) [toit] INFO: <- OK
(14.949808) [toit] INFO: -> AT
(14.954660) [toit] INFO: <- OK
(15.959295) [toit] INFO: -> AT
(15.964543) [toit] INFO: <- OK
(16.969490) [toit] INFO: -> AT
(16.975037) [toit] INFO: <- OK
(17.979519) [toit] INFO: -> AT
(17.985052) [toit] INFO: <- OK
(18.989507) [toit] INFO: -> AT
(18.994865) [toit] INFO: <- OK
(19.999739) [toit] INFO: -> AT
(20.004758) [toit] INFO: <- OK
(20.675424) [toit.scheduler] INFO: running job {job: persist_metrics}
(20.678857) [toit.metrics] INFO: persisting metrics
(20.913320) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
[gc @ 0x3ffcf9f0* | soft limit reached (53276 >= 49194)]
[gc @ 0x3ffcf9f0* | heap: 52kb -> 24kb | external: 0kb -> 0kb | used: 165kb | free: 10kb->78kb (largest 68kb) 6.573ms]
(21.009329) [toit] INFO: -> AT
(21.014938) [toit] INFO: <- OK
(22.019628) [toit] INFO: -> AT
(22.025259) [toit] INFO: <- OK
(23.029669) [toit] INFO: -> AT
(23.034899) [toit] INFO: <- OK
(24.041660) [toit] INFO: -> AT
(24.046568) [toit] INFO: <- OK
(25.050851) [toit] INFO: -> AT
(25.055803) [toit] INFO: <- OK
(26.060523) [toit] INFO: -> AT
(26.065701) [toit] INFO: <- OK
(27.070346) [toit] INFO: -> AT
(27.075122) [toit] INFO: <- OK
(27.751396) [toit] INFO: -> AT
(27.757887) [toit] INFO: <- OK
(28.008046) [toit] INFO: -> AT+CFUN=4
(28.199968) [toit] INFO: <- OK
(28.202848) [toit] INFO: <- +CEREG: 0
(28.204884) [toit] INFO: <- *ignored* [URC] +CEREG [0]
(28.206931) [toit.cellular] DEBUG: failed, detach from network
----
Received a Toit system message but unable to send it to the Toit console for decoding.
Executing the command below will make it human readable:
----
toit serial decode WyNVBVVYU1UXdjEuNi4wLXByZS4zMyszZmJhNGFlYTdTVQllc3AzMi00bWJbJFUjVRAAAAAAAAAAAAAAAAAAAAAAWyNVBFVFU1UJRVhDRVBUSU9OU1URQ09OTkVDVElPTiBGQUlMRURbI1UCVVNbI1UmWyNVA1VGVQBsAAI+PVsjVQNVRlUBbAACPq5bI1UDVUZVAmwAAjoxWyNVA1VGVQNsAAI6XFsjVQNVRlUEbAACrABbI1UDVUZVBUklaFsjVQNVRlUGSSV9WyNVA1VGVQdJJVpbI1UDVUZVCGwAAqy/WyNVA1VGVQlsAAKtWVsjVQNVRlUKbAACph9bI1UDVUZVC2wAAp8EWyNVA1VGVQxsAAKuCFsjVQNVRlUNbAACqppbI1UDVUZVDkklaFsjVQNVRlUPSSV9WyNVA1VGVRBJJQJbI1UDVUZVEWwAAqrXWyNVA1VGVRJsAAKqc1sjVQNVRlUTbAABA/hbI1UDVUZVFGwAAaD4WyNVA1VGVRVsAAEUPlsjVQNVRlUWbAABFFdbI1UDVUZVF2wAARPUWyNVA1VGVRhJJWhbI1UDVUZVGUklfVsjVQNVRlUaSSVaWyNVA1VGVRtsAAET7VsjVQNVRlUcbAABFANbI1UDVUZVHUkyqVsjVQNVRlUebAACTNhbI1UDVUZVH0klaFsjVQNVRlUgSSV9WyNVA1VGVSFJJQJbI1UDVUZVImwAAkztWyNVA1VGVSNsAAJNBFsjVQNVRlUkSTI+WyNVA1VGVSVJMtk=
(28.311454) [toit.network] DEBUG: error connecting {network: Cellular (nbiot.tdc.dk), error: CONNECTION FAILED}
[gc @ 0x3ffcf9f0* | soft limit reached (49773 >= 49194)]
[gc @ 0x3ffcf9f0* | heap: 48kb -> 24kb | external: 0kb -> 0kb | used: 157kb | free: 9kb->86kb (largest 72kb) 6.785ms]
(28.329719) [toit.network] WARN: failed to connect to any network
----
Received a Toit system message but unable to send it to the Toit console for decoding.
Executing the command below will make it human readable:
----
toit serial decode WyNVBVVYU1UXdjEuNi4wLXByZS4zMyszZmJhNGFlYTdTVQllc3AzMi00bWJbJFUjVRAAAAAAAAAAAAAAAAAAAAAAWyNVBFVFU1UJRVhDRVBUSU9OU1URRkFJTEVEIFRPIENPTk5FQ1RbI1UCVVNbI1UbWyNVA1VGVQBsAAKusVsjVQNVRlUBbAACrg5bI1UDVUZVAmwAAqqaWyNVA1VGVQNJJWhbI1UDVUZVBEklfVsjVQNVRlUFSSUCWyNVA1VGVQZsAAKq11sjVQNVRlUHbAACqnNbI1UDVUZVCGwAAQP4WyNVA1VGVQlsAAGg+FsjVQNVRlUKbAABFD5bI1UDVUZVC2wAARRXWyNVA1VGVQxsAAET1FsjVQNVRlUNSSVoWyNVA1VGVQ5JJX1bI1UDVUZVD0klWlsjVQNVRlUQbAABE+1bI1UDVUZVEWwAARQDWyNVA1VGVRJJMqlbI1UDVUZVE2wAAkzYWyNVA1VGVRRJJWhbI1UDVUZVFUklfVsjVQNVRlUWSSUCWyNVA1VGVRdsAAJM7VsjVQNVRlUYbAACTQRbI1UDVUZVGUkyPlsjVQNVRlUaSTLZ
(28.419965) [toit] INFO: -> AT+CFUN=0
(28.425718) [toit.scheduler] INFO: changing run level {run_level: 0}
(28.429283) [toit.scheduler] INFO: going into deep sleep {ms: 4988}
(28.431215) [toit.metrics] INFO: persisting metrics
(28.912835) [toit] INFO: <- OK
(29.020686) [toit] INFO: entering deep sleep {ms: 4988}
Entering deep sleep for 4988ms
ets Jun  8 2016 00:22:57

rst:0x5 (DEEPSLEEP_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0030,len:188
ho 0 tail 12 room 4
load:0x40078000,len:12180
load:0x40080400,len:2944
entry 0x400805c8
[flash reg] address 0x3f46c000, size 0x00134000
[IDENTITY] name=4c2a0869-49c3-4fe7-834e-ce3a6a9e2b7c.744.2021-09-26.device.toitware.com,model=esp32-4mb
(0.015830) [toit] INFO: booting toit {sdk: v1.6.0-pre.33+3fba4aea7, model: esp32-4mb}
(0.021979) [toit.scheduler] INFO: set initial run_level {run_level: 4}
(0.054299) [toit.state] INFO: resumed session {session_id: 1, session_time: 34.116767}
[gc @ 0x3ffcfa58* | soft limit reached (20480 >= 18432)]
[gc @ 0x3ffcfa58* | heap: 20kb -> 8kb | external: 0kb -> 0kb | used: 93kb | free: 9kb->149kb (largest 108kb) 3.164ms]
(0.074210) [toit.kernel] INFO: using model parameters {cellular.cts: 18, cellular.enabled: 1, cellular.monarch: 1, cellular.pwr: 27, cellular.rts: 19, cellular.rx: 23, cellular.tx: 5}
(0.110960) [toit.console_sync] INFO: loaded last console sync {time: 28.391512}
(0.127283) [toit.scheduler] INFO: running job {job: console_sync}
[gc @ 0x3ffcfa58* | soft limit reached (24576 >= 24576)]
[gc @ 0x3ffcfa58* | heap: 24kb -> 16kb | external: 0kb -> 0kb | used: 102kb | free: 8kb->140kb (largest 108kb) 5.032ms]
(0.130049) [toit.scheduler] INFO: running job {job: poll_metric_flash_usage}
(0.146906) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(0.156743) [toit.console] INFO: waiting for console connection to be established
(0.161068) [toit.network] DEBUG: connecting {network: Cellular (nbiot.tdc.dk)}
[gc @ 0x3ffcfa58* | soft limit reached (36892 >= 36864)]
[gc @ 0x3ffcfa58* | heap: 36kb -> 20kb | external: 0kb -> 0kb | used: 126kb | free: 12kb->116kb (largest 104kb) 5.513ms]
(0.210868) [toit] INFO: -> AT
(0.472264) [toit] INFO: -> AT
(0.732844) [toit] INFO: -> AT
(0.993544) [toit] INFO: -> AT
(1.254323) [toit] INFO: -> AT
(1.516299) [toit] INFO: -> AT
(1.777865) [toit] INFO: -> AT
(1.948454) [toit] INFO: <- OK
(2.054081) [toit] INFO: -> ATE0
(2.061973) [toit] INFO: <- OK
(2.084576) [toit] INFO: -> AT+CMEE=2
(2.090142) [toit] INFO: <- OK
[gc @ 0x3ffcfa58* | soft limit reached (45084 >= 43050)]
[gc @ 0x3ffcfa58* | heap: 44kb -> 20kb | external: 0kb -> 0kb | used: 149kb | free: 10kb->94kb (largest 84kb) 6.214ms]
(2.112616) [toit] INFO: -> AT+CGMM
(2.127080) [toit] INFO: <- FiPy
(2.129977) [toit] INFO: <- OK
(2.152108) [toit] INFO: -> AT+CGMR
(2.172974) [toit] INFO: <- UE5.4.0.2
(2.175836) [toit] INFO: <- OK
(2.206008) [toit] INFO: -> AT+SQNCCID?
(2.211445) [toit] INFO: <- +SQNCCID: "",""
(2.213987) [toit] INFO: <- OK
(2.216549) [toit.cellular] DEBUG: initialized {model: FiPy, version: UE5.4.0.2, iccid: }
(2.236361) [toit] INFO: -> AT+CFUN=4
(2.302632) [toit] INFO: <- OK
(2.324993) [toit] INFO: -> AT+CPIN?
(2.330609) [toit] INFO: <- +CME ERROR: SIM not inserted
(2.585453) [toit] INFO: -> AT+CPIN?
(2.591116) [toit] INFO: <- +CME ERROR: SIM not inserted
(2.845555) [toit] INFO: -> AT+CPIN?
(2.971605) [toit] INFO: <- +CPIN: READY
(2.974128) [toit] INFO: <- OK
(2.996444) [toit] INFO: -> AT+CEREG=2
(3.014829) [toit] INFO: <- OK
(3.037577) [toit] INFO: -> AT+CPSMS=0
(3.045011) [toit] INFO: <- OK
(3.067764) [toit] INFO: -> AT+CEDRXS=0
(3.075267) [toit] INFO: <- OK
(3.106269) [toit] INFO: -> AT+SQNIBRCFG=0
(3.127563) [toit] INFO: <- OK
(3.150256) [toit] INFO: -> AT+SQNIPSCFG=1,100
(3.168042) [toit] INFO: <- OK
(3.190807) [toit] INFO: -> AT+SQNBANDSEL=0,"standard","20"
(3.260222) [toit] INFO: <- +SQNBANDSEL: <custom>
(3.262875) [toit] INFO: <- OK
(3.285613) [toit] INFO: -> AT+SQNBANDSEL=1,"standard","20"
(3.292504) [toit] INFO: <- +CME ERROR: operation not supported
(3.314596) [toit] INFO: -> AT+CGDCONT?
(3.321496) [toit] INFO: <- +CGDCONT: 1,"IP","nbiot.tdc.dk",,,,0,0,0,0,0,0,0,,0
(3.324224) [toit] INFO: <- OK
(3.346561) [toit] INFO: -> AT+CFUN=1
(3.417895) [toit] INFO: <- OK
(3.894560) [toit] INFO: <- +CEREG: 2
(3.896715) [toit] INFO: <- [URC] +CEREG [2]
(3.898854) [toit.cellular] DEBUG: attempt modem's automatic connect
(3.910746) [toit.cellular] DEBUG: connecting {operator: null, attempt: 2}
(3.917607) [toit] INFO: -> AT+COPS?
(3.924476) [toit] INFO: <- +COPS: 0
(3.927002) [toit] INFO: <- OK
(3.949482) [toit] INFO: -> AT+CEREG=2
(3.959353) [toit] INFO: <- OK
(3.981727) [toit] INFO: -> AT+CEREG?
[gc @ 0x3ffcfa58* | soft limit reached (45084 >= 43050)]
[gc @ 0x3ffcfa58* | heap: 44kb -> 24kb | external: 0kb -> 0kb | used: 149kb | free: 10kb->94kb (largest 84kb) 6.409ms]
(3.986994) [toit] INFO: <- +CEREG: 2,2
(3.999793) [toit] INFO: <- OK
(5.004968) [toit] INFO: -> AT
(5.009745) [toit] INFO: <- OK
(6.014350) [toit] INFO: -> AT
(6.019595) [toit] INFO: <- OK
(7.024286) [toit] INFO: -> AT
(7.029147) [toit] INFO: <- OK
(8.033897) [toit] INFO: -> AT
(8.213524) [toit] INFO: <- OK
(8.216543) [toit] INFO: <- +CEREG: 5,"1BBC","00EEAE14",7
(8.218848) [toit] INFO: <- [URC] +CEREG [5, 1BBC, 00EEAE14, 7]
(8.221867) [toit.cellular] DEBUG: connected successfully
(8.238845) [toit] INFO: -> AT+COPS?
(8.355731) [toit] INFO: <- +COPS: 0,2,"23801",7
(8.358578) [toit] INFO: <- OK
(8.375413) [toit.network] DEBUG: connected {network: Cellular (nbiot.tdc.dk)}
(8.388037) [toit] INFO: -> AT+CSQ
(8.395311) [toit] INFO: <- +CSQ: 15,99
(8.398408) [toit] INFO: <- OK
(8.402143) [toit.console_conn] INFO: initialized {identity: 4c2a0869-49c3-4fe7-834e-ce3a6a9e2b7c.744.2021-09-26.device.toitware.com}
(8.421012) [toit] INFO: -> AT+SQNDNSLKUP="device.toit.io"
(8.879045) [toit] INFO: <- +SQNDNSLKUP: <custom>
(8.882033) [toit] INFO: <- OK
(8.937865) [toit.console_conn] INFO: connecting to console {host: 35.228.86.200:9426, common_name: device.toit.io, protocol: tls}
(8.941820) [toit] INFO: -> AT+SQNSCFG=1,1,300,0,80,50
(8.954816) [toit] INFO: <- OK
(8.978269) [toit] INFO: -> AT+SQNSD=1,0,9426,"35.228.86.200",0,0,1
(9.245834) [toit] INFO: <- OK
(9.270257) [toit] INFO: -> AT+SQNSSENDEXT=1,243
(9.277395) [toit] INFO: <- >
(9.279164) [toit] INFO: -> <243 bytes>
(9.283580) [toit] INFO: <-  
(9.285623) [toit] INFO: <- OK
(10.014000) [toit] INFO: <- +SQNSRING: 1
(10.016260) [toit] INFO: <- [URC] +SQNSRING [1]
(10.036790) [toit] INFO: -> AT+SQNSI=1
(10.043233) [toit] INFO: <- +SQNSI: 1,243,846,846,0
(10.046053) [toit] INFO: <- OK
(10.068396) [toit] INFO: -> AT+SQNSRECV=1,1500
(10.075489) [toit] INFO: <- +SQNSRECV: <custom>
[gc @ 0x3ffcfa58* | soft limit reached (53276 >= 49194)]
[gc @ 0x3ffcfa58* | byte array allocation failed, length = 846 (heap)]
[gc @ 0x3ffcfa58* | heap: 52kb -> 28kb | external: 0kb -> 0kb | used: 187kb | free: 12kb->56kb (largest 44kb) 7.099ms]
(10.096904) [toit] INFO: <- OK
(10.149449) [toit.scheduler] INFO: running job {job: persist_metrics}
(10.154674) [toit] INFO: -> AT+CSQ
(10.161076) [toit] INFO: <- +CSQ: 15,99
(10.164223) [toit] INFO: <- OK
(10.167223) [toit.metrics] INFO: persisting metrics
(10.230168) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(12.909697) [toit] INFO: -> AT+SQNSSENDEXT=1,855
(12.917068) [toit] INFO: <- >
(12.918848) [toit] INFO: -> <855 bytes>
(12.932245) [toit] INFO: <-  
(12.934310) [toit] INFO: <- OK
(12.956946) [toit] INFO: -> AT+SQNSI=1
(12.962818) [toit] INFO: <- +SQNSI: 1,1098,846,0,855
(12.965945) [toit] INFO: <- OK
(13.200909) [toit] INFO: <- +SQNSRING: 1
(13.203110) [toit] INFO: <- [URC] +SQNSRING [1]
(13.214020) [toit] INFO: <- +SQNSRING: 1
(13.216305) [toit] INFO: <- [URC] +SQNSRING [1]
(13.236659) [toit] INFO: -> AT+SQNSI=1
(13.242614) [toit] INFO: <- +SQNSI: 1,1098,1645,799,0
(13.245370) [toit] INFO: <- OK
(13.267829) [toit] INFO: -> AT+SQNSRECV=1,1500
(13.273629) [toit] INFO: <- +SQNSRECV: <custom>
(13.282929) [toit] INFO: <- OK
(13.306565) [toit.console_conn] INFO: established
(13.318007) [toit] INFO: -> AT+SQNSSENDEXT=1,31
(13.324932) [toit] INFO: <- >
(13.326710) [toit] INFO: -> <31 bytes>
(13.328502) [toit] INFO: <-  
(13.330301) [toit] INFO: <- OK
(13.334063) [toit.console] INFO: connected, starting main loop
[gc @ 0x3ffcfa58* | soft limit reached (57372 >= 55338)]
[gc @ 0x3ffcfa58* | byte array allocation failed, length = 511 (heap)]
[gc @ 0x3ffcfa58* | heap: 56kb -> 28kb | external: 0kb -> 0kb | used: 197kb | free: 14kb->46kb (largest 32kb) 7.099ms]
(13.365717) [toit] INFO: -> AT+SQNSSENDEXT=1,52
(13.372842) [toit] INFO: <- >
(13.374424) [toit] INFO: -> <52 bytes>
(13.376213) [toit] INFO: <-  
(13.378262) [toit] INFO: <- OK
(13.400617) [toit] INFO: -> AT+SQNSI=1
(13.406422) [toit] INFO: <- +SQNSI: 1,1181,1645,0,83
(13.409485) [toit] INFO: <- OK
(13.431816) [toit] INFO: -> AT+SQNSSENDEXT=1,68
(13.437054) [toit] INFO: <- >
(13.438801) [toit] INFO: -> <68 bytes>
(13.440514) [toit] INFO: <-  
(13.442284) [toit] INFO: <- OK
(13.686656) [toit] INFO: <- +SQNSRING: 1
(13.688965) [toit] INFO: <- [URC] +SQNSRING [1]
(13.709472) [toit] INFO: -> AT+SQNSI=1
(13.715442) [toit] INFO: <- +SQNSI: 1,1249,1735,90,0
(13.718264) [toit] INFO: <- OK
(13.740551) [toit] INFO: -> AT+SQNSRECV=1,1500
(13.746601) [toit] INFO: <- +SQNSRECV: <custom>
(13.749524) [toit] INFO: <- OK
(13.759859) [toit.time] INFO: adjusting time by 455075h23m27.093243966s, accuracy: null -> 398769000 ns
(13.766589) [toit.console] INFO: received action {action: new epoch}
(13.768905) [toit.console] INFO: new epoch ed708eff-fbf2-4a31-9a62-91af5f32ae61
(13.785183) [toit] INFO: -> AT+SQNSSENDEXT=1,52
(13.793021) [toit] INFO: <- >
(13.794798) [toit] INFO: -> <52 bytes>
(13.796585) [toit] INFO: <-  
(13.798387) [toit] INFO: <- OK
(13.820907) [toit] INFO: -> AT+SQNSI=1
(13.826950) [toit] INFO: <- +SQNSI: 1,1301,1735,0,52
(13.829875) [toit] INFO: <- OK
(13.852221) [toit] INFO: -> AT+SQNSSENDEXT=1,86
[gc @ 0x3ffcfa58* | soft limit reached (57372 >= 55338)]
[gc @ 0x3ffcfa58* | heap: 56kb -> 32kb | external: 0kb -> 0kb | used: 197kb | free: 13kb->45kb (largest 32kb) 7.613ms]
(13.867112) [toit] INFO: <- >
(13.869138) [toit] INFO: -> <86 bytes>
(13.873314) [toit] INFO: <-  
(13.875793) [toit] INFO: <- OK
(14.138772) [toit] INFO: <- +SQNSRING: 1
(14.141505) [toit] INFO: <- [URC] +SQNSRING [1]
(14.161929) [toit] INFO: -> AT+SQNSI=1
(14.167916) [toit] INFO: <- +SQNSI: 1,1387,1789,54,0
(14.170710) [toit] INFO: <- OK
(14.192986) [toit] INFO: -> AT+SQNSRECV=1,1500
(14.198826) [toit] INFO: <- +SQNSRECV: <custom>
(14.201928) [toit] INFO: <- OK
(14.224194) [toit] INFO: -> AT+SQNSSENDEXT=1,52
(14.229898) [toit] INFO: <- >
(14.231592) [toit] INFO: -> <52 bytes>
(14.233566) [toit] INFO: <-  
(14.235404) [toit] INFO: <- OK
(14.257768) [toit] INFO: -> AT+SQNSI=1
(14.263744) [toit] INFO: <- +SQNSI: 1,1439,1789,0,52
(14.267011) [toit] INFO: <- OK
(14.289404) [toit] INFO: -> AT+SQNSSENDEXT=1,58
(14.294714) [toit] INFO: <- >
(14.296367) [toit] INFO: -> <58 bytes>
(14.298144) [toit] INFO: <-  
(14.299910) [toit] INFO: <- OK
(14.792448) [toit] INFO: <- +SQNSRING: 1
(14.794614) [toit] INFO: <- [URC] +SQNSRING [1]
(14.815220) [toit] INFO: -> AT+SQNSI=1
(14.820957) [toit] INFO: <- +SQNSI: 1,1497,1861,72,0
(14.823727) [toit] INFO: <- OK
(14.846080) [toit] INFO: -> AT+SQNSRECV=1,1500
(14.851849) [toit] INFO: <- +SQNSRECV: <custom>
(14.854707) [toit] INFO: <- OK
(14.864027) [toit.console] INFO: received action {action: report config}
(14.865749) [toit.console] INFO: reporting config
(14.877394) [toit] INFO: -> AT+SQNSSENDEXT=1,52
(14.883017) [toit] INFO: <- >
(14.884368) [toit] INFO: -> <52 bytes>
(14.886516) [toit] INFO: <-  
(14.888479) [toit] INFO: <- OK
(14.910597) [toit] INFO: -> AT+SQNSI=1
(14.916688) [toit] INFO: <- +SQNSI: 1,1549,1861,0,52
(14.919644) [toit] INFO: <- OK
(14.942040) [toit] INFO: -> AT+SQNSSENDEXT=1,235
(14.947443) [toit] INFO: <- >
(14.948906) [toit] INFO: -> <235 bytes>
(14.952109) [toit] INFO: <-  
(14.954201) [toit] INFO: <- OK
(15.204730) [toit] INFO: <- +SQNSRING: 1
(15.214157) [toit] INFO: <- [URC] +SQNSRING [1]
(15.227952) [toit] INFO: -> AT+SQNSI=1
(15.233862) [toit] INFO: <- +SQNSI: 1,1784,1915,54,0
(15.236660) [toit] INFO: <- OK
(15.259008) [toit] INFO: -> AT+SQNSRECV=1,1500
(15.264935) [toit] INFO: <- +SQNSRECV: <custom>
(15.267863) [toit] INFO: <- OK
(15.290245) [toit] INFO: -> AT+SQNSSENDEXT=1,52
(15.296027) [toit] INFO: <- >
(15.297842) [toit] INFO: -> <52 bytes>
(15.299821) [toit] INFO: <-  
(15.301632) [toit] INFO: <- OK
(15.323759) [toit] INFO: -> AT+SQNSI=1
(15.329631) [toit] INFO: <- +SQNSI: 1,1836,1915,0,52
(15.332582) [toit] INFO: <- OK
(15.354932) [toit] INFO: -> AT+SQNSSENDEXT=1,58
(15.360361) [toit] INFO: <- >
(15.362009) [toit] INFO: -> <58 bytes>
(15.363749) [toit] INFO: <-  
(15.365763) [toit] INFO: <- OK
(16.336917) [toit] INFO: -> AT
(16.341334) [toit] INFO: <- OK
(17.211731) [toit] INFO: <- +SQNSRING: 1
(17.213987) [toit] INFO: <- [URC] +SQNSRING [1]
(17.234571) [toit] INFO: -> AT+SQNSI=1
(17.240530) [toit] INFO: <- +SQNSI: 1,1894,2188,273,0
(17.243318) [toit] INFO: <- OK
(17.265668) [toit] INFO: -> AT+SQNSRECV=1,1500
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | string allocation failed, length = 47 (heap)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.655ms]
(17.271320) [toit] INFO: <- +SQNSRECV: <custom>
(17.289087) [toit] INFO: <- OK
(17.302942) [toit.console] INFO: received action {action: config update}
(17.324550) [toit.kernel] INFO: using model parameters {cellular.cts: 18, cellular.enabled: 1, cellular.monarch: 1, cellular.pwr: 27, cellular.rts: 19, cellular.rx: 23, cellular.tx: 5}
(17.333088) [toit.console] INFO: config updated: 3236313
(17.344697) [toit] INFO: -> AT+SQNSSENDEXT=1,52
(17.351058) [toit] INFO: <- >
(17.352588) [toit] INFO: -> <52 bytes>
(17.354358) [toit] INFO: <-  
(17.356169) [toit] INFO: <- OK
(17.379550) [toit] INFO: -> AT+SQNSI=1
(17.385803) [toit] INFO: <- +SQNSI: 1,1946,2188,0,52
(17.388749) [toit] INFO: <- OK
(17.414992) [toit] INFO: -> AT+SQNSSENDEXT=1,60
(17.420299) [toit] INFO: <- >
(17.421733) [toit] INFO: -> <60 bytes>
(17.423407) [toit] INFO: <-  
(17.425173) [toit] INFO: <- OK
(17.669678) [toit] INFO: <- +SQNSRING: 1
(17.672278) [toit] INFO: <- [URC] +SQNSRING [1]
(17.692764) [toit] INFO: -> AT+SQNSI=1
(17.698732) [toit] INFO: <- +SQNSI: 1,2006,2260,72,0
(17.701574) [toit] INFO: <- OK
(17.723900) [toit] INFO: -> AT+SQNSRECV=1,1500
(17.729636) [toit] INFO: <- +SQNSRECV: <custom>
(17.732582) [toit] INFO: <- OK
(17.741886) [toit.console] INFO: synchronized with console
[gc @ 0x3ffcfa58* | soft limit reached (61698 >= 61482)]
[gc @ 0x3ffcfa58* | heap: 60kb -> 36kb | external: 0kb -> 0kb | used: 205kb | free: 13kb->37kb (largest 16kb) 8.426ms]
(17.785671) [toit] INFO: -> AT+SQNSI=1
(17.793151) [toit] INFO: <- +SQNSI: 1,2006,2260,0,0
(17.796452) [toit] INFO: <- OK
(17.819235) [toit] INFO: -> AT+SQNSSENDEXT=1,55
(17.824792) [toit] INFO: <- >
(17.826259) [toit] INFO: -> <55 bytes>
(17.827955) [toit] INFO: <-  
(17.830129) [toit] INFO: <- OK
(17.852614) [toit] INFO: -> AT+SQNSSENDEXT=1,1268
(17.858479) [toit] INFO: <- >
(17.860010) [toit] INFO: -> <1268 bytes>
(17.877782) [toit] INFO: <-  
(17.879839) [toit] INFO: <- OK
(17.902139) [toit] INFO: -> AT+SQNSSENDEXT=1,55
(17.914956) [toit] INFO: <- >
(17.916763) [toit] INFO: -> <55 bytes>
(17.918515) [toit] INFO: <-  
(17.920603) [toit] INFO: <- OK
(18.801119) [toit] INFO: -> AT
(18.805715) [toit] INFO: <- OK
(19.387868) [toit] INFO: <- +SQNSRING: 1
(19.390098) [toit] INFO: <- [URC] +SQNSRING [1]
(19.399449) [toit] INFO: <- +SQNSRING: 1
(19.401710) [toit] INFO: <- [URC] +SQNSRING [1]
(19.422158) [toit] INFO: -> AT+SQNSI=1
(19.427912) [toit] INFO: <- +SQNSI: 1,3384,2342,82,0
(19.430703) [toit] INFO: <- OK
(19.453233) [toit] INFO: -> AT+SQNSRECV=1,1500
(19.459001) [toit] INFO: <- +SQNSRECV: <custom>
(19.461845) [toit] INFO: <- OK
(19.494864) [toit] INFO: -> AT+SQNSI=1
(19.502223) [toit] INFO: <- +SQNSI: 1,3384,2342,0,0
(19.505058) [toit] INFO: <- OK
(19.527934) [toit] INFO: -> AT+SQNSSENDEXT=1,55
(19.533649) [toit] INFO: <- >
(19.535108) [toit] INFO: -> <55 bytes>
(19.536984) [toit] INFO: <-  
(19.538802) [toit] INFO: <- OK
[gc @ 0x3ffcfa58* | soft limit reached (69660 >= 67626)]
[gc @ 0x3ffcfa58* | heap: 68kb -> 32kb | external: 0kb -> 0kb | used: 221kb | free: 13kb->21kb (largest 8kb) 7.785ms]
(19.570724) [toit] INFO: -> AT+SQNSSENDEXT=1,36
(19.576587) [toit] INFO: <- >
(19.578267) [toit] INFO: -> <36 bytes>
(19.580106) [toit] INFO: <-  
(19.581901) [toit] INFO: <- OK
(19.604925) [toit] INFO: -> AT+SQNSSENDEXT=1,56
(19.615373) [toit] INFO: <- >
(19.617017) [toit] INFO: -> <56 bytes>
(19.618867) [toit] INFO: <-  
(19.620666) [toit] INFO: <- OK
(20.220015) [toit.scheduler] INFO: running job {job: persist_metrics}
(20.224939) [toit] INFO: -> AT+CSQ
(20.230846) [toit] INFO: <- +CSQ: 14,99
(20.233600) [toit] INFO: <- OK
(20.236536) [toit.metrics] INFO: persisting metrics
(20.272995) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(20.517031) [toit] INFO: -> AT
(20.522549) [toit] INFO: <- OK
(21.527159) [toit] INFO: -> AT
(21.531541) [toit] INFO: <- OK
(22.535938) [toit] INFO: -> AT
(22.540263) [toit] INFO: <- OK
(23.544917) [toit] INFO: -> AT
(23.549375) [toit] INFO: <- OK
(24.553762) [toit] INFO: -> AT
(24.558110) [toit] INFO: <- OK
(25.562709) [toit] INFO: -> AT
(25.567512) [toit] INFO: <- OK
(26.572383) [toit] INFO: -> AT
(26.576736) [toit] INFO: <- OK
(27.581162) [toit] INFO: -> AT
(27.585403) [toit] INFO: <- OK
(28.589805) [toit] INFO: -> AT
(28.594038) [toit] INFO: <- OK
(29.598575) [toit] INFO: -> AT
(29.603099) [toit] INFO: <- OK
(30.292943) [toit.scheduler] INFO: running job {job: persist_metrics}
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 8kb) 7.621ms]
(30.314118) [toit] INFO: -> AT+CSQ
(30.318572) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(30.327365) [toit] INFO: <- +CSQ: 16,99
(30.329735) [toit] INFO: <- OK
(30.332474) [toit.metrics] INFO: persisting metrics
(30.616995) [toit] INFO: -> AT
(30.622316) [toit] INFO: <- OK
(31.627185) [toit] INFO: -> AT
(31.631504) [toit] INFO: <- OK
(32.635881) [toit] INFO: -> AT
(32.640367) [toit] INFO: <- OK
(33.644779) [toit] INFO: -> AT
(33.649043) [toit] INFO: <- OK
(34.653439) [toit] INFO: -> AT
(34.657701) [toit] INFO: <- OK
(35.662159) [toit] INFO: -> AT
(35.667115) [toit] INFO: <- OK
(36.671666) [toit] INFO: -> AT
(36.676074) [toit] INFO: <- OK
(37.680473) [toit] INFO: -> AT
(37.684941) [toit] INFO: <- OK
(38.689304) [toit] INFO: -> AT
(38.693640) [toit] INFO: <- OK
(39.698655) [toit] INFO: -> AT
(39.702973) [toit] INFO: <- OK
(40.366881) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(40.395914) [toit.scheduler] INFO: running job {job: persist_metrics}
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.688ms]
(40.409424) [toit] INFO: -> AT+CSQ
(40.415708) [toit] INFO: <- +CSQ: 16,99
(40.418368) [toit] INFO: <- OK
(40.421298) [toit.metrics] INFO: persisting metrics
(40.715500) [toit] INFO: -> AT
(40.720321) [toit] INFO: <- OK
(41.724921) [toit] INFO: -> AT
(41.729291) [toit] INFO: <- OK
(42.733705) [toit] INFO: -> AT
(42.737926) [toit] INFO: <- OK
(43.742560) [toit] INFO: -> AT
(43.746839) [toit] INFO: <- OK
(44.751265) [toit] INFO: -> AT
(44.755596) [toit] INFO: <- OK
(45.759969) [toit] INFO: -> AT
(45.764692) [toit] INFO: <- OK
(46.769429) [toit] INFO: -> AT
(46.773692) [toit] INFO: <- OK
(47.778378) [toit] INFO: -> AT
(47.782682) [toit] INFO: <- OK
(48.787021) [toit] INFO: -> AT
(48.791356) [toit] INFO: <- OK
(49.795973) [toit] INFO: -> AT
(49.800290) [toit] INFO: <- OK
(50.415845) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(50.463545) [toit.scheduler] INFO: running job {job: persist_metrics}
(50.468182) [toit] INFO: -> AT+CSQ
(50.473974) [toit] INFO: <- +CSQ: 16,99
(50.476794) [toit] INFO: <- OK
(50.479705) [toit.metrics] INFO: persisting metrics
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | byte array allocation failed, length = 606 (heap)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.630ms]
(50.816488) [toit] INFO: -> AT
(50.821224) [toit] INFO: <- OK
(51.825962) [toit] INFO: -> AT
(51.830357) [toit] INFO: <- OK
(52.834758) [toit] INFO: -> AT
(52.839078) [toit] INFO: <- OK
(53.843441) [toit] INFO: -> AT
(53.847794) [toit] INFO: <- OK
(54.852413) [toit] INFO: -> AT
(54.856729) [toit] INFO: <- OK
(55.861297) [toit] INFO: -> AT
(55.866136) [toit] INFO: <- OK
(56.870881) [toit] INFO: -> AT
(56.875163) [toit] INFO: <- OK
(57.879868) [toit] INFO: -> AT
(57.884163) [toit] INFO: <- OK
(58.888604) [toit] INFO: -> AT
(58.892882) [toit] INFO: <- OK
(59.897313) [toit] INFO: -> AT
(59.901581) [toit] INFO: <- OK
(60.390534) [toit.scheduler] INFO: running job {job: poll_metric_flash_usage}
(60.459530) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(60.520621) [toit.scheduler] INFO: running job {job: persist_metrics}
(60.525017) [toit] INFO: -> AT+CSQ
(60.530867) [toit] INFO: <- +CSQ: 16,99
(60.533998) [toit] INFO: <- OK
(60.536929) [toit.metrics] INFO: persisting metrics
(60.905987) [toit] INFO: -> AT
(60.915696) [toit] INFO: <- OK
(61.920133) [toit] INFO: -> AT
(61.924474) [toit] INFO: <- OK
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | byte array allocation failed, length = 606 (heap)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.570ms]
(62.940572) [toit] INFO: -> AT
(62.944994) [toit] INFO: <- OK
(63.949618) [toit] INFO: -> AT
(63.953950) [toit] INFO: <- OK
(64.958366) [toit] INFO: -> AT
(64.962657) [toit] INFO: <- OK
(65.967212) [toit] INFO: -> AT
(65.971909) [toit] INFO: <- OK
(66.976843) [toit] INFO: -> AT
(66.981121) [toit] INFO: <- OK
(67.985551) [toit] INFO: -> AT
(67.989816) [toit] INFO: <- OK
(68.994215) [toit] INFO: -> AT
(68.998475) [toit] INFO: <- OK
(70.003112) [toit] INFO: -> AT
(70.007401) [toit] INFO: <- OK
(70.503729) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(70.577888) [toit.scheduler] INFO: running job {job: persist_metrics}
(70.582606) [toit] INFO: -> AT+CSQ
(70.588357) [toit] INFO: <- +CSQ: 16,99
(70.591188) [toit] INFO: <- OK
(70.594075) [toit.metrics] INFO: persisting metrics
(71.012247) [toit] INFO: -> AT
(71.016784) [toit] INFO: <- OK
(72.021517) [toit] INFO: -> AT
(72.025860) [toit] INFO: <- OK
(73.030299) [toit] INFO: -> AT
(73.034593) [toit] INFO: <- OK
(74.039232) [toit] INFO: -> AT
(74.043512) [toit] INFO: <- OK
(75.048496) [toit] INFO: -> AT
(75.052777) [toit] INFO: <- OK
(76.057146) [toit] INFO: -> AT
(76.061794) [toit] INFO: <- OK
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | byte array allocation failed, length = 606 (heap)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.609ms]
(77.078103) [toit] INFO: -> AT
(77.082504) [toit] INFO: <- OK
(78.087216) [toit] INFO: -> AT
(78.091523) [toit] INFO: <- OK
(79.095923) [toit] INFO: -> AT
(79.100219) [toit] INFO: <- OK
(80.104611) [toit] INFO: -> AT
(80.113015) [toit] INFO: <- OK
(80.550357) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(80.637731) [toit.scheduler] INFO: running job {job: persist_metrics}
(80.642228) [toit] INFO: -> AT+CSQ
(80.647913) [toit] INFO: <- +CSQ: 16,99
(80.651024) [toit] INFO: <- OK
(80.653974) [toit.metrics] INFO: persisting metrics
(81.117622) [toit] INFO: -> AT
(81.122140) [toit] INFO: <- OK
(82.126707) [toit] INFO: -> AT
(82.131378) [toit] INFO: <- OK
(82.622603) [toit] INFO: <- +SQNSRING: 1
(82.624924) [toit] INFO: <- [URC] +SQNSRING [1]
(82.645719) [toit] INFO: -> AT+SQNSI=1
(82.651904) [toit] INFO: <- +SQNSI: 1,3531,2389,47,0
(82.654714) [toit] INFO: <- OK
(82.677051) [toit] INFO: -> AT+SQNSRECV=1,1500
(82.684676) [toit] INFO: <- +SQNSRECV: <custom>
(82.687674) [toit] INFO: <- OK
(82.710016) [toit] INFO: -> AT+SQNSI=1
(82.717331) [toit] INFO: <- +SQNSI: 1,3531,2389,0,0
(82.720396) [toit] INFO: <- OK
(83.725022) [toit] INFO: -> AT
(83.729474) [toit] INFO: <- OK
(84.733813) [toit] INFO: -> AT
(84.738379) [toit] INFO: <- OK
(85.061039) [toit] INFO: <- +CEREG: 5,"1BBC","0059C514",7
(85.063465) [toit] INFO: <- *ignored* [URC] +CEREG [5, 1BBC, 0059C514, 7]
(85.743077) [toit] INFO: -> AT
(85.747797) [toit] INFO: <- OK
(86.752298) [toit] INFO: -> AT
(86.756708) [toit] INFO: <- OK
(87.761079) [toit] INFO: -> AT
(87.765755) [toit] INFO: <- OK
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | byte array allocation failed, length = 606 (heap)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.609ms]
(88.781814) [toit] INFO: -> AT
(88.786537) [toit] INFO: <- OK
(89.791183) [toit] INFO: -> AT
(89.795582) [toit] INFO: <- OK
(90.595216) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(90.696111) [toit.scheduler] INFO: running job {job: persist_metrics}
(90.700659) [toit] INFO: -> AT+CSQ
(90.706572) [toit] INFO: <- +CSQ: 17,99
(90.709416) [toit] INFO: <- OK
(90.712312) [toit.metrics] INFO: persisting metrics
(90.801390) [toit] INFO: -> AT
(90.806601) [toit] INFO: <- OK
(91.811424) [toit] INFO: -> AT
(91.815872) [toit] INFO: <- OK
(92.820276) [toit] INFO: -> AT
(92.824556) [toit] INFO: <- OK
(93.829354) [toit] INFO: -> AT
(93.833703) [toit] INFO: <- OK
(94.838431) [toit] INFO: -> AT
(94.842770) [toit] INFO: <- OK
(95.847401) [toit] INFO: -> AT
(95.852201) [toit] INFO: <- OK
(96.857066) [toit] INFO: -> AT
(96.861362) [toit] INFO: <- OK
(97.865789) [toit] INFO: -> AT
(97.869979) [toit] INFO: <- OK
(98.874357) [toit] INFO: -> AT
(98.878608) [toit] INFO: <- OK
(99.883255) [toit] INFO: -> AT
(99.887510) [toit] INFO: <- OK
(100.641844) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.631ms]
(100.763838) [toit.scheduler] INFO: running job {job: persist_metrics}
(100.768463) [toit] INFO: -> AT+CSQ
(100.774243) [toit] INFO: <- +CSQ: 16,99
(100.777403) [toit] INFO: <- OK
(100.780382) [toit.metrics] INFO: persisting metrics
(100.893131) [toit] INFO: -> AT
(100.898284) [toit] INFO: <- OK
(101.903171) [toit] INFO: -> AT
(101.907524) [toit] INFO: <- OK
(102.912162) [toit] INFO: -> AT
(102.916359) [toit] INFO: <- OK
(103.920802) [toit] INFO: -> AT
(103.925125) [toit] INFO: <- OK
(104.929583) [toit] INFO: -> AT
(104.933876) [toit] INFO: <- OK
(105.938781) [toit] INFO: -> AT
(105.943557) [toit] INFO: <- OK
(106.948368) [toit] INFO: -> AT
(106.952612) [toit] INFO: <- OK
(107.956997) [toit] INFO: -> AT
(107.961289) [toit] INFO: <- OK
(108.965880) [toit] INFO: -> AT
(108.970212) [toit] INFO: <- OK
(109.974597) [toit] INFO: -> AT
(109.978887) [toit] INFO: <- OK
(110.696653) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(110.832271) [toit.scheduler] INFO: running job {job: persist_metrics}
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.671ms]
(110.845815) [toit] INFO: -> AT+CSQ
(110.852199) [toit] INFO: <- +CSQ: 16,99
(110.855020) [toit] INFO: <- OK
(110.857929) [toit.metrics] INFO: persisting metrics
(110.983475) [toit] INFO: -> AT
(110.987942) [toit] INFO: <- OK
(111.992392) [toit] INFO: -> AT
(111.996958) [toit] INFO: <- OK
(113.001365) [toit] INFO: -> AT
(113.006020) [toit] INFO: <- OK
(114.010646) [toit] INFO: -> AT
(114.014984) [toit] INFO: <- OK
(115.019353) [toit] INFO: -> AT
(115.023656) [toit] INFO: <- OK
(116.028860) [toit] INFO: -> AT
(116.033666) [toit] INFO: <- OK
(117.038768) [toit] INFO: -> AT
(117.043004) [toit] INFO: <- OK
(118.047447) [toit] INFO: -> AT
(118.051892) [toit] INFO: <- OK
(119.056327) [toit] INFO: -> AT
(119.060628) [toit] INFO: <- OK
(120.065298) [toit] INFO: -> AT
(120.069585) [toit] INFO: <- OK
(120.623504) [toit.scheduler] INFO: running job {job: poll_metric_flash_usage}
(120.741062) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(120.899556) [toit.scheduler] INFO: running job {job: persist_metrics}
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.634ms]
(120.912956) [toit] INFO: -> AT+CSQ
(120.919548) [toit] INFO: <- +CSQ: 16,99
(120.922415) [toit] INFO: <- OK
(120.925323) [toit.metrics] INFO: persisting metrics
(121.074140) [toit] INFO: -> AT
(121.078853) [toit] INFO: <- OK
(122.083332) [toit] INFO: -> AT
(122.087676) [toit] INFO: <- OK
(123.092020) [toit] INFO: -> AT
(123.096387) [toit] INFO: <- OK
(124.100999) [toit] INFO: -> AT
(124.105376) [toit] INFO: <- OK
(125.109727) [toit] INFO: -> AT
(125.114060) [toit] INFO: <- OK
(126.118628) [toit] INFO: -> AT
(126.123580) [toit] INFO: <- OK
(127.129232) [toit] INFO: -> AT
(127.133917) [toit] INFO: <- OK
(128.138504) [toit] INFO: -> AT
(128.142800) [toit] INFO: <- OK
(128.738490) [toit] INFO: <- +CEREG: 5,"1BBC","0059C514",7
(128.740997) [toit] INFO: <- *ignored* [URC] +CEREG [5, 1BBC, 0059C514, 7]
(129.147364) [toit] INFO: -> AT
(129.151916) [toit] INFO: <- OK
(130.156140) [toit] INFO: -> AT
(130.160500) [toit] INFO: <- OK
(130.783244) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(130.964916) [toit.scheduler] INFO: running job {job: persist_metrics}
(130.969510) [toit] INFO: -> AT+CSQ
(130.975336) [toit] INFO: <- +CSQ: 15,99
(130.978182) [toit] INFO: <- OK
(130.981068) [toit.metrics] INFO: persisting metrics
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 8.227ms]
(131.166322) [toit] INFO: -> AT
(131.171591) [toit] INFO: <- OK
(132.176260) [toit] INFO: -> AT
(132.180692) [toit] INFO: <- OK
(133.185056) [toit] INFO: -> AT
(133.189421) [toit] INFO: <- OK
(134.194069) [toit] INFO: -> AT
(134.198408) [toit] INFO: <- OK
(135.202791) [toit] INFO: -> AT
(135.207157) [toit] INFO: <- OK
(136.211746) [toit] INFO: -> AT
(136.216554) [toit] INFO: <- OK
(137.221407) [toit] INFO: -> AT
(137.225738) [toit] INFO: <- OK
(138.230285) [toit] INFO: -> AT
(138.234575) [toit] INFO: <- OK
(139.238979) [toit] INFO: -> AT
(139.243220) [toit] INFO: <- OK
(140.248707) [toit] INFO: -> AT
(140.253069) [toit] INFO: <- OK
(140.826361) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(141.030218) [toit.scheduler] INFO: running job {job: persist_metrics}
(141.034973) [toit] INFO: -> AT+CSQ
(141.040731) [toit] INFO: <- +CSQ: 16,99
(141.043579) [toit] INFO: <- OK
(141.046495) [toit.metrics] INFO: persisting metrics
(141.258705) [toit] INFO: -> AT
(141.263870) [toit] INFO: <- OK
(142.268742) [toit] INFO: -> AT
(142.273078) [toit] INFO: <- OK
(143.277470) [toit] INFO: -> AT
(143.281741) [toit] INFO: <- OK
(144.286413) [toit] INFO: -> AT
(144.290675) [toit] INFO: <- OK
(145.295087) [toit] INFO: -> AT
(145.299327) [toit] INFO: <- OK
(145.550707) [toit] INFO: <- +SQNSRING: 1
(145.553040) [toit] INFO: <- [URC] +SQNSRING [1]
(145.573679) [toit] INFO: -> AT+SQNSI=1
(145.579659) [toit] INFO: <- +SQNSI: 1,3531,2436,47,0
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.705ms]
(145.591330) [toit] INFO: <- OK
(145.614111) [toit] INFO: -> AT+SQNSRECV=1,1500
(145.620598) [toit] INFO: <- +SQNSRECV: <custom>
(145.623530) [toit] INFO: <- OK
(145.645811) [toit] INFO: -> AT+SQNSI=1
(145.651891) [toit] INFO: <- +SQNSI: 1,3531,2436,0,0
(145.655340) [toit] INFO: <- OK
(146.659685) [toit] INFO: -> AT
(146.664412) [toit] INFO: <- OK
(147.669275) [toit] INFO: -> AT
(147.673500) [toit] INFO: <- OK
(148.678473) [toit] INFO: -> AT
(148.682719) [toit] INFO: <- OK
(149.687100) [toit] INFO: -> AT
(149.691331) [toit] INFO: <- OK
(150.695918) [toit] INFO: -> AT
(150.700352) [toit] INFO: <- OK
(150.867959) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(151.099401) [toit.scheduler] INFO: running job {job: persist_metrics}
(151.104083) [toit] INFO: -> AT+CSQ
(151.109874) [toit] INFO: <- +CSQ: 15,99
(151.112718) [toit] INFO: <- OK
(151.115600) [toit.metrics] INFO: persisting metrics
(151.705971) [toit] INFO: -> AT
(151.711262) [toit] INFO: <- OK
(152.716169) [toit] INFO: -> AT
(152.720533) [toit] INFO: <- OK
(153.724932) [toit] INFO: -> AT
(153.729185) [toit] INFO: <- OK
(154.733907) [toit] INFO: -> AT
(154.738229) [toit] INFO: <- OK
(155.742663) [toit] INFO: -> AT
(155.746912) [toit] INFO: <- OK
(156.751433) [toit] INFO: -> AT
(156.756203) [toit] INFO: <- OK
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | byte array allocation failed, length = 606 (heap)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.610ms]
(157.772467) [toit] INFO: -> AT
(157.776835) [toit] INFO: <- OK
(158.781509) [toit] INFO: -> AT
(158.785887) [toit] INFO: <- OK
(159.790264) [toit] INFO: -> AT
(159.794544) [toit] INFO: <- OK
(160.798911) [toit] INFO: -> AT
(160.803228) [toit] INFO: <- OK
(160.909522) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(161.168976) [toit.scheduler] INFO: running job {job: persist_metrics}
(161.173397) [toit] INFO: -> AT+CSQ
(161.179283) [toit] INFO: <- +CSQ: 15,99
(161.182395) [toit] INFO: <- OK
(161.185368) [toit.metrics] INFO: persisting metrics
(161.808352) [toit] INFO: -> AT
(161.812909) [toit] INFO: <- OK
(162.818341) [toit] INFO: -> AT
(162.822753) [toit] INFO: <- OK
(163.827392) [toit] INFO: -> AT
(163.831723) [toit] INFO: <- OK
(164.836159) [toit] INFO: -> AT
(164.840607) [toit] INFO: <- OK
(165.844862) [toit] INFO: -> AT
(165.849332) [toit] INFO: <- OK
(166.854144) [toit] INFO: -> AT
(166.858907) [toit] INFO: <- OK
(167.863620) [toit] INFO: -> AT
(167.868025) [toit] INFO: <- OK
(168.872448) [toit] INFO: -> AT
(168.876693) [toit] INFO: <- OK
(169.881370) [toit] INFO: -> AT
(169.885708) [toit] INFO: <- OK
(170.890130) [toit] INFO: -> AT
(170.894372) [toit] INFO: <- OK
(170.949777) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.620ms]
(171.222392) [toit.scheduler] INFO: running job {job: persist_metrics}
(171.227140) [toit] INFO: -> AT+CSQ
(171.233054) [toit] INFO: <- +CSQ: 16,99
(171.235988) [toit] INFO: <- OK
(171.238908) [toit.metrics] INFO: persisting metrics
(171.900004) [toit] INFO: -> AT
(171.905256) [toit] INFO: <- OK
(172.910162) [toit] INFO: -> AT
(172.914580) [toit] INFO: <- OK
(173.540533) [toit] INFO: <- +CEREG: 5,"1BBC","00EEAE14",7
(173.543072) [toit] INFO: <- *ignored* [URC] +CEREG [5, 1BBC, 00EEAE14, 7]
(173.919275) [toit] INFO: -> AT
(173.923779) [toit] INFO: <- OK
(174.928383) [toit] INFO: -> AT
(174.934255) [toit] INFO: <- OK
(175.938513) [toit] INFO: -> AT
(175.942820) [toit] INFO: <- OK
(176.947529) [toit] INFO: -> AT
(176.952228) [toit] INFO: <- OK
(177.956918) [toit] INFO: -> AT
(177.961203) [toit] INFO: <- OK
(178.965607) [toit] INFO: -> AT
(178.969897) [toit] INFO: <- OK
(179.974534) [toit] INFO: -> AT
(179.978819) [toit] INFO: <- OK
(180.832538) [toit.scheduler] INFO: running job {job: poll_metric_flash_usage}
(180.983229) [toit] INFO: -> AT
(180.988084) [toit] INFO: <- OK
(180.998762) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.644ms]
(181.286519) [toit.scheduler] INFO: running job {job: persist_metrics}
(181.291118) [toit] INFO: -> AT+CSQ
(181.297147) [toit] INFO: <- +CSQ: 16,99
(181.300054) [toit] INFO: <- OK
(181.303002) [toit.metrics] INFO: persisting metrics
(181.992751) [toit] INFO: -> AT
(181.997713) [toit] INFO: <- OK
(183.002254) [toit] INFO: -> AT
(183.006918) [toit] INFO: <- OK
(183.858144) [toit] INFO: <- +CEREG: 5,"1BBC","0059C514",7
(183.860591) [toit] INFO: <- *ignored* [URC] +CEREG [5, 1BBC, 0059C514, 7]
(184.011780) [toit] INFO: -> AT
(184.016358) [toit] INFO: <- OK
(185.020611) [toit] INFO: -> AT
(185.025119) [toit] INFO: <- OK
(186.035239) [toit] INFO: -> AT
(186.039547) [toit] INFO: <- OK
(186.338288) [toit] INFO: <- +CEREG: 5,"1BBC","00EEAE14",7
(186.340684) [toit] INFO: <- *ignored* [URC] +CEREG [5, 1BBC, 00EEAE14, 7]
(187.043996) [toit] INFO: -> AT
(187.048575) [toit] INFO: <- OK
(188.052796) [toit] INFO: -> AT
(188.057179) [toit] INFO: <- OK
(189.061851) [toit] INFO: -> AT
(189.066176) [toit] INFO: <- OK
(190.070576) [toit] INFO: -> AT
(190.074959) [toit] INFO: <- OK
(191.048679) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(191.079322) [toit] INFO: -> AT
(191.084240) [toit] INFO: <- OK
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.648ms]
(191.348663) [toit.scheduler] INFO: running job {job: persist_metrics}
(191.356150) [toit] INFO: -> AT+CSQ
(191.361366) [toit] INFO: <- +CSQ: 17,99
(191.364211) [toit] INFO: <- OK
(191.367128) [toit.metrics] INFO: persisting metrics
(192.090130) [toit] INFO: -> AT
(192.095388) [toit] INFO: <- OK
(193.100445) [toit] INFO: -> AT
(193.104726) [toit] INFO: <- OK
(194.109410) [toit] INFO: -> AT
(194.113818) [toit] INFO: <- OK
(195.118513) [toit] INFO: -> AT
(195.122705) [toit] INFO: <- OK
(196.134301) [toit] INFO: -> AT
(196.138574) [toit] INFO: <- OK
(197.143291) [toit] INFO: -> AT
(197.148103) [toit] INFO: <- OK
(198.152659) [toit] INFO: -> AT
(198.156973) [toit] INFO: <- OK
(199.161376) [toit] INFO: -> AT
(199.165726) [toit] INFO: <- OK
(200.170342) [toit] INFO: -> AT
(200.174584) [toit] INFO: <- OK
(201.088794) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(201.179047) [toit] INFO: -> AT
(201.183793) [toit] INFO: <- OK
(201.417816) [toit.scheduler] INFO: running job {job: persist_metrics}
(201.422424) [toit] INFO: -> AT+CSQ
(201.427955) [toit] INFO: <- +CSQ: 15,99
(201.430566) [toit] INFO: <- OK
(201.433492) [toit.metrics] INFO: persisting metrics
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.767ms]
(202.189898) [toit] INFO: -> AT
(202.195308) [toit] INFO: <- OK
(203.200005) [toit] INFO: -> AT
(203.204621) [toit] INFO: <- OK
(204.209008) [toit] INFO: -> AT
(204.213508) [toit] INFO: <- OK
(204.648161) [toit] INFO: <- +SQNSRING: 1
(204.650427) [toit] INFO: <- [URC] +SQNSRING [1]
(204.671170) [toit] INFO: -> AT+SQNSI=1
(204.677339) [toit] INFO: <- +SQNSI: 1,3531,2483,47,0
(204.680146) [toit] INFO: <- OK
(204.702481) [toit] INFO: -> AT+SQNSRECV=1,1500
(204.708135) [toit] INFO: <- +SQNSRECV: <custom>
(204.710967) [toit] INFO: <- OK
(204.733328) [toit] INFO: -> AT+SQNSI=1
(204.739442) [toit] INFO: <- +SQNSI: 1,3531,2483,0,0
(204.742511) [toit] INFO: <- OK
(205.746933) [toit] INFO: -> AT
(205.751313) [toit] INFO: <- OK
(206.755653) [toit] INFO: -> AT
(206.760517) [toit] INFO: <- OK
(207.765300) [toit] INFO: -> AT
(207.769757) [toit] INFO: <- OK
(208.774166) [toit] INFO: -> AT
(208.778590) [toit] INFO: <- OK
(209.782950) [toit] INFO: -> AT
(209.787460) [toit] INFO: <- OK
(210.791832) [toit] INFO: -> AT
(210.796205) [toit] INFO: <- OK
(211.126964) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(211.485059) [toit.scheduler] INFO: running job {job: persist_metrics}
(211.489831) [toit] INFO: -> AT+CSQ
(211.495394) [toit] INFO: <- +CSQ: 15,99
(211.498277) [toit] INFO: <- OK
(211.501239) [toit.metrics] INFO: persisting metrics
(211.801287) [toit] INFO: -> AT
(211.805852) [toit] INFO: <- OK
(212.810387) [toit] INFO: -> AT
(212.814786) [toit] INFO: <- OK
(213.819202) [toit] INFO: -> AT
(213.823478) [toit] INFO: <- OK
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | byte array allocation failed, length = 606 (heap)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.574ms]
(214.840141) [toit] INFO: -> AT
(214.844448) [toit] INFO: <- OK
(215.849115) [toit] INFO: -> AT
(215.853407) [toit] INFO: <- OK
(216.858473) [toit] INFO: -> AT
(216.863191) [toit] INFO: <- OK
(217.868374) [toit] INFO: -> AT
(217.872758) [toit] INFO: <- OK
(218.337787) [toit] INFO: <- +CEREG: 5,"1BBC","0059C514",7
(218.340251) [toit] INFO: <- *ignored* [URC] +CEREG [5, 1BBC, 0059C514, 7]
(218.877293) [toit] INFO: -> AT
(218.881769) [toit] INFO: <- OK
(219.885958) [toit] INFO: -> AT
(219.890311) [toit] INFO: <- OK
(220.894949) [toit] INFO: -> AT
(220.899810) [toit] INFO: <- OK
(220.902603) [toit] INFO: <- +CEREG: 5,"1BBC","00EEAE14",7
(220.904816) [toit] INFO: <- *ignored* [URC] +CEREG [5, 1BBC, 00EEAE14, 7]
(221.168241) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(221.539954) [toit.scheduler] INFO: running job {job: persist_metrics}
(221.544660) [toit] INFO: -> AT+CSQ
(221.550555) [toit] INFO: <- +CSQ: 15,99
(221.553369) [toit] INFO: <- OK
(221.556323) [toit.metrics] INFO: persisting metrics
(221.908918) [toit] INFO: -> AT
(221.913458) [toit] INFO: <- OK
(222.918366) [toit] INFO: -> AT
(222.922724) [toit] INFO: <- OK
(223.927104) [toit] INFO: -> AT
(223.931433) [toit] INFO: <- OK
(224.936040) [toit] INFO: -> AT
(224.940415) [toit] INFO: <- OK
(225.944820) [toit] INFO: -> AT
(225.949214) [toit] INFO: <- OK
(226.953685) [toit] INFO: -> AT
(226.958423) [toit] INFO: <- OK
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | byte array allocation failed, length = 606 (heap)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.600ms]
(227.974774) [toit] INFO: -> AT
(227.979082) [toit] INFO: <- OK
(228.983744) [toit] INFO: -> AT
(228.988022) [toit] INFO: <- OK
(229.992409) [toit] INFO: -> AT
(229.996677) [toit] INFO: <- OK
(231.001254) [toit] INFO: -> AT
(231.005490) [toit] INFO: <- OK
(231.210484) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(231.595696) [toit.scheduler] INFO: running job {job: persist_metrics}
(231.600174) [toit] INFO: -> AT+CSQ
(231.606057) [toit] INFO: <- +CSQ: 16,99
(231.609141) [toit] INFO: <- OK
(231.612105) [toit.metrics] INFO: persisting metrics
(232.011217) [toit] INFO: -> AT
(232.016489) [toit] INFO: <- OK
(233.021294) [toit] INFO: -> AT
(233.026019) [toit] INFO: <- OK
(234.030430) [toit] INFO: -> AT
(234.034735) [toit] INFO: <- OK
(235.040205) [toit] INFO: -> AT
(235.044645) [toit] INFO: <- OK
(236.048933) [toit] INFO: -> AT
(236.053255) [toit] INFO: <- OK
(237.058859) [toit] INFO: -> AT
(237.063668) [toit] INFO: <- OK
(238.068469) [toit] INFO: -> AT
(238.072696) [toit] INFO: <- OK
(239.077117) [toit] INFO: -> AT
(239.081373) [toit] INFO: <- OK
(240.085993) [toit] INFO: -> AT
(240.090474) [toit] INFO: <- OK
(241.035505) [toit.scheduler] INFO: running job {job: poll_metric_flash_usage}
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.639ms]
(241.094855) [toit] INFO: -> AT
(241.099910) [toit] INFO: <- OK
(241.250624) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(241.657137) [toit.scheduler] INFO: running job {job: persist_metrics}
(241.661764) [toit] INFO: -> AT+CSQ
(241.667816) [toit] INFO: <- +CSQ: 16,99
(241.670683) [toit] INFO: <- OK
(241.673595) [toit.metrics] INFO: persisting metrics
(242.104683) [toit] INFO: -> AT
(242.109363) [toit] INFO: <- OK
(243.113879) [toit] INFO: -> AT
(243.118283) [toit] INFO: <- OK
(244.122656) [toit] INFO: -> AT
(244.126990) [toit] INFO: <- OK
(245.131650) [toit] INFO: -> AT
(245.135992) [toit] INFO: <- OK
(246.141642) [toit] INFO: -> AT
(246.146187) [toit] INFO: <- OK
(247.150711) [toit] INFO: -> AT
(247.155507) [toit] INFO: <- OK
(248.160376) [toit] INFO: -> AT
(248.164671) [toit] INFO: <- OK
(249.169091) [toit] INFO: -> AT
(249.173399) [toit] INFO: <- OK
(250.178461) [toit] INFO: -> AT
(250.182682) [toit] INFO: <- OK
(251.187324) [toit] INFO: -> AT
(251.191617) [toit] INFO: <- OK
(251.288179) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.613ms]
(251.707723) [toit.scheduler] INFO: running job {job: persist_metrics}
(251.712265) [toit] INFO: -> AT+CSQ
(251.718087) [toit] INFO: <- +CSQ: 16,99
(251.721221) [toit] INFO: <- OK
(251.724193) [toit.metrics] INFO: persisting metrics
(252.196095) [toit] INFO: -> AT
(252.200628) [toit] INFO: <- OK
(253.205169) [toit] INFO: -> AT
(253.209526) [toit] INFO: <- OK
(254.214175) [toit] INFO: -> AT
(254.218456) [toit] INFO: <- OK
(255.222827) [toit] INFO: -> AT
(255.227085) [toit] INFO: <- OK
(256.231490) [toit] INFO: -> AT
(256.235812) [toit] INFO: <- OK
(257.240586) [toit] INFO: -> AT
(257.245722) [toit] INFO: <- OK
(258.250356) [toit] INFO: -> AT
(258.254679) [toit] INFO: <- OK
(259.259093) [toit] INFO: -> AT
(259.263348) [toit] INFO: <- OK
(260.268609) [toit] INFO: -> AT
(260.272957) [toit] INFO: <- OK
(261.200778) [toit] INFO: <- +SQNSRING: 1
(261.203024) [toit] INFO: <- [URC] +SQNSRING [1]
(261.223694) [toit] INFO: -> AT+SQNSI=1
(261.230651) [toit] INFO: <- +SQNSI: 1,3531,2530,47,0
(261.233466) [toit] INFO: <- OK
(261.255823) [toit] INFO: -> AT+SQNSRECV=1,1500
(261.261420) [toit] INFO: <- +SQNSRECV: <custom>
(261.264519) [toit] INFO: <- OK
(261.287748) [toit] INFO: -> AT+SQNSI=1
(261.293754) [toit] INFO: <- +SQNSI: 1,3531,2530,0,0
(261.296823) [toit] INFO: <- OK
(261.335594) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(261.758443) [toit.scheduler] INFO: running job {job: persist_metrics}
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.738ms]
(261.772702) [toit] INFO: -> AT+CSQ
(261.778703) [toit] INFO: <- +CSQ: 14,99
(261.781535) [toit] INFO: <- OK
(261.784420) [toit.metrics] INFO: persisting metrics
(262.302371) [toit] INFO: -> AT
(262.307795) [toit] INFO: <- OK
(263.312695) [toit] INFO: -> AT
(263.317181) [toit] INFO: <- OK
(264.321572) [toit] INFO: -> AT
(264.326310) [toit] INFO: <- OK
(265.330995) [toit] INFO: -> AT
(265.335507) [toit] INFO: <- OK
(266.340031) [toit] INFO: -> AT
(266.344581) [toit] INFO: <- OK
(267.349068) [toit] INFO: -> AT
(267.353876) [toit] INFO: <- OK
(268.358672) [toit] INFO: -> AT
(268.363032) [toit] INFO: <- OK
(269.368394) [toit] INFO: -> AT
(269.372651) [toit] INFO: <- OK
(270.377014) [toit] INFO: -> AT
(270.381329) [toit] INFO: <- OK
(271.373154) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(271.386052) [toit] INFO: -> AT
(271.390796) [toit] INFO: <- OK
(271.834979) [toit.scheduler] INFO: running job {job: persist_metrics}
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.756ms]
(271.848596) [toit] INFO: -> AT+CSQ
(271.854300) [toit] INFO: <- +CSQ: 18,99
(271.856936) [toit] INFO: <- OK
(271.859827) [toit.metrics] INFO: persisting metrics
(272.396688) [toit] INFO: -> AT
(272.402030) [toit] INFO: <- OK
(273.406936) [toit] INFO: -> AT
(273.411325) [toit] INFO: <- OK
(274.415714) [toit] INFO: -> AT
(274.419950) [toit] INFO: <- OK
(275.424627) [toit] INFO: -> AT
(275.428923) [toit] INFO: <- OK
(276.433337) [toit] INFO: -> AT
(276.437641) [toit] INFO: <- OK
(277.442109) [toit] INFO: -> AT
(277.447131) [toit] INFO: <- OK
(278.451919) [toit] INFO: -> AT
(278.456250) [toit] INFO: <- OK
(279.460672) [toit] INFO: -> AT
(279.465062) [toit] INFO: <- OK
(280.469429) [toit] INFO: -> AT
(280.473747) [toit] INFO: <- OK
(281.413288) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(281.478447) [toit] INFO: -> AT
(281.483209) [toit] INFO: <- OK
(281.907643) [toit.scheduler] INFO: running job {job: persist_metrics}
(281.912407) [toit] INFO: -> AT+CSQ
(281.917998) [toit] INFO: <- +CSQ: 16,99
(281.920760) [toit] INFO: <- OK
(281.923689) [toit.metrics] INFO: persisting metrics
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.662ms]
(282.489710) [toit] INFO: -> AT
(282.495057) [toit] INFO: <- OK
(283.499909) [toit] INFO: -> AT
(283.504238) [toit] INFO: <- OK
(284.508607) [toit] INFO: -> AT
(284.512909) [toit] INFO: <- OK
(285.518509) [toit] INFO: -> AT
(285.522791) [toit] INFO: <- OK
(286.527192) [toit] INFO: -> AT
(286.531483) [toit] INFO: <- OK
(287.535921) [toit] INFO: -> AT
(287.540775) [toit] INFO: <- OK
(288.545313) [toit] INFO: -> AT
(288.549580) [toit] INFO: <- OK
(289.554044) [toit] INFO: -> AT
(289.558478) [toit] INFO: <- OK
(290.562728) [toit] INFO: -> AT
(290.567117) [toit] INFO: <- OK
(291.451878) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(291.571572) [toit] INFO: -> AT
(291.576449) [toit] INFO: <- OK
(291.976109) [toit.scheduler] INFO: running job {job: persist_metrics}
(291.980830) [toit] INFO: -> AT+CSQ
(291.986451) [toit] INFO: <- +CSQ: 15,99
(291.989185) [toit] INFO: <- OK
(291.992135) [toit.metrics] INFO: persisting metrics
(292.582348) [toit] INFO: -> AT
(292.587575) [toit] INFO: <- OK
(293.592481) [toit] INFO: -> AT
(293.596815) [toit] INFO: <- OK
(294.601210) [toit] INFO: -> AT
(294.605543) [toit] INFO: <- OK
(295.610239) [toit] INFO: -> AT
(295.614505) [toit] INFO: <- OK
(296.618914) [toit] INFO: -> AT
(296.623180) [toit] INFO: <- OK
(297.628568) [toit] INFO: -> AT
(297.633302) [toit] INFO: <- OK
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | byte array allocation failed, length = 606 (heap)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.602ms]
(298.652339) [toit] INFO: -> AT
(298.656754) [toit] INFO: <- OK
(299.661434) [toit] INFO: -> AT
(299.665820) [toit] INFO: <- OK
(300.670197) [toit] INFO: -> AT
(300.674532) [toit] INFO: <- OK
(301.236068) [toit.scheduler] INFO: running job {job: poll_metric_flash_usage}
(301.490078) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(301.679354) [toit] INFO: -> AT
(301.684231) [toit] INFO: <- OK
(302.035295) [toit.scheduler] INFO: running job {job: persist_metrics}
(302.039782) [toit] INFO: -> AT+CSQ
(302.044969) [toit] INFO: <- +CSQ: 16,99
(302.047866) [toit] INFO: <- OK
(302.050856) [toit.metrics] INFO: persisting metrics
(302.690208) [toit] INFO: -> AT
(302.695365) [toit] INFO: <- OK
(303.700240) [toit] INFO: -> AT
(303.704580) [toit] INFO: <- OK
(304.708972) [toit] INFO: -> AT
(304.713251) [toit] INFO: <- OK
(305.718509) [toit] INFO: -> AT
(305.722755) [toit] INFO: <- OK
(306.727165) [toit] INFO: -> AT
(306.731441) [toit] INFO: <- OK
(307.736116) [toit] INFO: -> AT
(307.740839) [toit] INFO: <- OK
(308.745393) [toit] INFO: -> AT
(308.750095) [toit] INFO: <- OK
(309.754500) [toit] INFO: -> AT
(309.759039) [toit] INFO: <- OK
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | byte array allocation failed, length = 606 (heap)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.617ms]
(310.775104) [toit] INFO: -> AT
(310.779479) [toit] INFO: <- OK
(311.523963) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(311.783882) [toit] INFO: -> AT
(311.792658) [toit] INFO: <- OK
(312.092318) [toit.scheduler] INFO: running job {job: persist_metrics}
(312.097279) [toit] INFO: -> AT+CSQ
(312.102727) [toit] INFO: <- +CSQ: 16,99
(312.105573) [toit] INFO: <- OK
(312.108454) [toit.metrics] INFO: persisting metrics
(312.797370) [toit] INFO: -> AT
(312.801944) [toit] INFO: <- OK
(313.806536) [toit] INFO: -> AT
(313.810892) [toit] INFO: <- OK
(314.815307) [toit] INFO: -> AT
(314.819567) [toit] INFO: <- OK
(315.824206) [toit] INFO: -> AT
(315.828487) [toit] INFO: <- OK
(316.832913) [toit] INFO: -> AT
(316.837141) [toit] INFO: <- OK
(317.841520) [toit] INFO: -> AT
(317.846238) [toit] INFO: <- OK
(318.855436) [toit] INFO: -> AT
(318.859901) [toit] INFO: <- OK
(319.864197) [toit] INFO: -> AT
(319.868555) [toit] INFO: <- OK
(320.872893) [toit] INFO: -> AT
(320.877407) [toit] INFO: <- OK
(321.079793) [toit] INFO: <- +SQNSRING: 1
(321.082315) [toit] INFO: <- [URC] +SQNSRING [1]
(321.102949) [toit] INFO: -> AT+SQNSI=1
(321.108810) [toit] INFO: <- +SQNSI: 1,3531,2577,47,0
(321.111625) [toit] INFO: <- OK
(321.133947) [toit] INFO: -> AT+SQNSRECV=1,1500
(321.139551) [toit] INFO: <- +SQNSRECV: <custom>
(321.142395) [toit] INFO: <- OK
(321.164801) [toit] INFO: -> AT+SQNSI=1
(321.170669) [toit] INFO: <- +SQNSI: 1,3531,2577,0,0
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | string allocation failed, length = 6 (heap)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.750ms]
(321.173762) [toit] INFO: <- OK
(321.556015) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(322.137734) [toit.scheduler] INFO: running job {job: persist_metrics}
(322.142462) [toit] INFO: -> AT+CSQ
(322.148889) [toit] INFO: <- +CSQ: 15,99
(322.151648) [toit] INFO: <- OK
(322.154474) [toit.metrics] INFO: persisting metrics
(322.194317) [toit] INFO: -> AT
(322.199358) [toit] INFO: <- OK
(323.204257) [toit] INFO: -> AT
(323.208580) [toit] INFO: <- OK
(324.213003) [toit] INFO: -> AT
(324.217300) [toit] INFO: <- OK
(325.221991) [toit] INFO: -> AT
(325.226347) [toit] INFO: <- OK
(326.230787) [toit] INFO: -> AT
(326.235184) [toit] INFO: <- OK
(327.239825) [toit] INFO: -> AT
(327.244738) [toit] INFO: <- OK
(328.249601) [toit] INFO: -> AT
(328.253904) [toit] INFO: <- OK
(329.258866) [toit] INFO: -> AT
(329.263127) [toit] INFO: <- OK
(329.702114) [toit] INFO: <- +CEREG: 5,"1BBC","0059C514",7
(329.704661) [toit] INFO: <- *ignored* [URC] +CEREG [5, 1BBC, 0059C514, 7]
(330.267712) [toit] INFO: -> AT
(330.272335) [toit] INFO: <- OK
(331.276582) [toit] INFO: -> AT
(331.280980) [toit] INFO: <- OK
(331.586351) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(332.197297) [toit.scheduler] INFO: running job {job: persist_metrics}
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.689ms]
(332.212434) [toit] INFO: -> AT+CSQ
(332.218146) [toit] INFO: <- +CSQ: 15,99
(332.221151) [toit] INFO: <- OK
(332.224144) [toit.metrics] INFO: persisting metrics
(332.285515) [toit] INFO: -> AT
(332.290053) [toit] INFO: <- OK
(333.294590) [toit] INFO: -> AT
(333.298906) [toit] INFO: <- OK
(334.303548) [toit] INFO: -> AT
(334.307850) [toit] INFO: <- OK
(335.312217) [toit] INFO: -> AT
(335.316528) [toit] INFO: <- OK
(336.320930) [toit] INFO: -> AT
(336.325251) [toit] INFO: <- OK
(337.329884) [toit] INFO: -> AT
(337.334640) [toit] INFO: <- OK
(338.339317) [toit] INFO: -> AT
(338.343709) [toit] INFO: <- OK
(339.348394) [toit] INFO: -> AT
(339.352720) [toit] INFO: <- OK
(340.357396) [toit] INFO: -> AT
(340.361743) [toit] INFO: <- OK
(341.366211) [toit] INFO: -> AT
(341.370693) [toit] INFO: <- OK
(341.616033) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(342.251015) [toit.scheduler] INFO: running job {job: persist_metrics}
(342.255839) [toit] INFO: -> AT+CSQ
(342.261430) [toit] INFO: <- +CSQ: 16,99
(342.264153) [toit] INFO: <- OK
(342.267061) [toit.metrics] INFO: persisting metrics
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.674ms]
(342.376328) [toit] INFO: -> AT
(342.381587) [toit] INFO: <- OK
(343.386319) [toit] INFO: -> AT
(343.390669) [toit] INFO: <- OK
(344.395042) [toit] INFO: -> AT
(344.399362) [toit] INFO: <- OK
(345.404013) [toit] INFO: -> AT
(345.408290) [toit] INFO: <- OK
(346.412683) [toit] INFO: -> AT
(346.417007) [toit] INFO: <- OK
(347.421438) [toit] INFO: -> AT
(347.426234) [toit] INFO: <- OK
(348.430763) [toit] INFO: -> AT
(348.435184) [toit] INFO: <- OK
(349.439588) [toit] INFO: -> AT
(349.443914) [toit] INFO: <- OK
(350.448358) [toit] INFO: -> AT
(350.452674) [toit] INFO: <- OK
(351.457299) [toit] INFO: -> AT
(351.461749) [toit] INFO: <- OK
(351.647047) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(352.308369) [toit.scheduler] INFO: running job {job: persist_metrics}
(352.313001) [toit] INFO: -> AT+CSQ
(352.319032) [toit] INFO: <- +CSQ: 16,99
(352.321871) [toit] INFO: <- OK
(352.324796) [toit.metrics] INFO: persisting metrics
(352.466365) [toit] INFO: -> AT
(352.470971) [toit] INFO: <- OK
(353.475421) [toit] INFO: -> AT
(353.479842) [toit] INFO: <- OK
(354.484196) [toit] INFO: -> AT
(354.488528) [toit] INFO: <- OK
(355.493142) [toit] INFO: -> AT
(355.497602) [toit] INFO: <- OK
(356.501848) [toit] INFO: -> AT
(356.506241) [toit] INFO: <- OK
(357.510781) [toit] INFO: -> AT
(357.515486) [toit] INFO: <- OK
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | byte array allocation failed, length = 606 (heap)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.610ms]
(358.531944) [toit] INFO: -> AT
(358.536309) [toit] INFO: <- OK
(359.541005) [toit] INFO: -> AT
(359.545352) [toit] INFO: <- OK
(360.549777) [toit] INFO: -> AT
(360.554029) [toit] INFO: <- OK
(361.386656) [toit.scheduler] INFO: running job {job: poll_metric_flash_usage}
(361.560392) [toit] INFO: -> AT
(361.565390) [toit] INFO: <- OK
(361.678939) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(362.352911) [toit.scheduler] INFO: running job {job: persist_metrics}
(362.357542) [toit] INFO: -> AT+CSQ
(362.363578) [toit] INFO: <- +CSQ: 15,99
(362.366430) [toit] INFO: <- OK
(362.369369) [toit.metrics] INFO: persisting metrics
(362.571153) [toit] INFO: -> AT
(362.576439) [toit] INFO: <- OK
(363.581260) [toit] INFO: -> AT
(363.585740) [toit] INFO: <- OK
(364.590147) [toit] INFO: -> AT
(364.594482) [toit] INFO: <- OK
(365.599175) [toit] INFO: -> AT
(365.603527) [toit] INFO: <- OK
(366.608429) [toit] INFO: -> AT
(366.612694) [toit] INFO: <- OK
(367.617338) [toit] INFO: -> AT
(367.622163) [toit] INFO: <- OK
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | byte array allocation failed, length = 606 (heap)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.609ms]
(368.638477) [toit] INFO: -> AT
(368.642775) [toit] INFO: <- OK
(369.647458) [toit] INFO: -> AT
(369.651728) [toit] INFO: <- OK
(370.656105) [toit] INFO: -> AT
(370.662654) [toit] INFO: <- OK
(371.667128) [toit] INFO: -> AT
(371.671461) [toit] INFO: <- OK
(371.708514) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(372.406921) [toit.scheduler] INFO: running job {job: persist_metrics}
(372.411426) [toit] INFO: -> AT+CSQ
(372.417377) [toit] INFO: <- +CSQ: 15,99
(372.420508) [toit] INFO: <- OK
(372.423510) [toit.metrics] INFO: persisting metrics
(372.675938) [toit] INFO: -> AT
(372.680509) [toit] INFO: <- OK
(373.685036) [toit] INFO: -> AT
(373.689450) [toit] INFO: <- OK
(374.694090) [toit] INFO: -> AT
(374.698433) [toit] INFO: <- OK
(375.702836) [toit] INFO: -> AT
(375.707107) [toit] INFO: <- OK
(376.711489) [toit] INFO: -> AT
(376.715882) [toit] INFO: <- OK
(377.720707) [toit] INFO: -> AT
(377.725472) [toit] INFO: <- OK
(378.730097) [toit] INFO: -> AT
(378.734347) [toit] INFO: <- OK
(379.738770) [toit] INFO: -> AT
(379.743002) [toit] INFO: <- OK
(380.747627) [toit] INFO: -> AT
(380.751868) [toit] INFO: <- OK
(381.738515) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.653ms]
(381.758019) [toit] INFO: -> AT
(381.762884) [toit] INFO: <- OK
(382.350865) [toit] INFO: <- +SQNSRING: 1
(382.353099) [toit] INFO: <- [URC] +SQNSRING [1]
(382.373812) [toit] INFO: -> AT+SQNSI=1
(382.379569) [toit] INFO: <- +SQNSI: 1,3531,2624,47,0
(382.382388) [toit] INFO: <- OK
(382.404747) [toit] INFO: -> AT+SQNSRECV=1,1500
(382.410325) [toit] INFO: <- +SQNSRECV: <custom>
(382.413447) [toit] INFO: <- OK
(382.435803) [toit] INFO: -> AT+SQNSI=1
(382.442677) [toit] INFO: <- +SQNSI: 1,3531,2624,0,0
(382.445743) [toit] INFO: <- OK
(382.450841) [toit.scheduler] INFO: running job {job: persist_metrics}
(382.467921) [toit] INFO: -> AT+CSQ
(382.473253) [toit] INFO: <- +CSQ: 14,99
(382.476024) [toit] INFO: <- OK
(382.478948) [toit.metrics] INFO: persisting metrics
(383.451358) [toit] INFO: -> AT
(383.456990) [toit] INFO: <- OK
(384.461988) [toit] INFO: -> AT
(384.466441) [toit] INFO: <- OK
(385.470743) [toit] INFO: -> AT
(385.475267) [toit] INFO: <- OK
(386.479959) [toit] INFO: -> AT
(386.484237) [toit] INFO: <- OK
(387.497379) [toit] INFO: -> AT
(387.502206) [toit] INFO: <- OK
(388.506624) [toit] INFO: -> AT
(388.511085) [toit] INFO: <- OK
(389.515752) [toit] INFO: -> AT
(389.520027) [toit] INFO: <- OK
(390.524451) [toit] INFO: -> AT
(390.528692) [toit] INFO: <- OK
(391.533100) [toit] INFO: -> AT
(391.537418) [toit] INFO: <- OK
(391.777297) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 36kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.711ms]
(392.515916) [toit.scheduler] INFO: running job {job: persist_metrics}
(392.520602) [toit] INFO: -> AT+CSQ
(392.526768) [toit] INFO: <- +CSQ: 17,99
(392.529817) [toit] INFO: <- OK
(392.532829) [toit.metrics] INFO: persisting metrics
(392.552899) [toit] INFO: -> AT
(392.558582) [toit] INFO: <- OK
(393.563529) [toit] INFO: -> AT
(393.568015) [toit] INFO: <- OK
(394.572516) [toit] INFO: -> AT
(394.576993) [toit] INFO: <- OK
(395.581392) [toit] INFO: -> AT
(395.585795) [toit] INFO: <- OK
(396.590154) [toit] INFO: -> AT
(396.594526) [toit] INFO: <- OK
(397.599205) [toit] INFO: -> AT
(397.604042) [toit] INFO: <- OK
(398.608660) [toit] INFO: -> AT
(398.613154) [toit] INFO: <- OK
(398.817769) [toit] INFO: <- +CEREG: 5,"1BBC","00EEAE14",7
(398.820245) [toit] INFO: <- *ignored* [URC] +CEREG [5, 1BBC, 00EEAE14, 7]
(399.618664) [toit] INFO: -> AT
(399.623259) [toit] INFO: <- OK
(400.628337) [toit] INFO: -> AT
(400.632762) [toit] INFO: <- OK
(401.637140) [toit] INFO: -> AT
(401.641463) [toit] INFO: <- OK
(401.814038) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(402.565876) [toit.scheduler] INFO: running job {job: persist_metrics}
(402.570546) [toit] INFO: -> AT+CSQ
(402.576105) [toit] INFO: <- +CSQ: 16,99
[gc @ 0x3ffcfa58* | soft limit reached (69660 >= 67626)]
[gc @ 0x3ffcfa58* | heap: 68kb -> 36kb | external: 0kb -> 0kb | used: 222kb | free: 13kb->21kb (largest 8kb) 7.790ms]
(402.588802) [toit] INFO: <- OK
(402.592009) [toit.metrics] INFO: persisting metrics
(402.647214) [toit] INFO: -> AT
(402.652515) [toit] INFO: <- OK
(403.662998) [toit] INFO: -> AT
(403.667404) [toit] INFO: <- OK
(404.672046) [toit] INFO: -> AT
(404.676371) [toit] INFO: <- OK
(405.680812) [toit] INFO: -> AT
(405.685233) [toit] INFO: <- OK
(406.689659) [toit] INFO: -> AT
(406.693931) [toit] INFO: <- OK
(407.698778) [toit] INFO: -> AT
(407.703514) [toit] INFO: <- OK
(408.708373) [toit] INFO: -> AT
(408.712723) [toit] INFO: <- OK
(409.717106) [toit] INFO: -> AT
(409.721409) [toit] INFO: <- OK
(410.725996) [toit] INFO: -> AT
(410.730331) [toit] INFO: <- OK
(411.734712) [toit] INFO: -> AT
(411.739024) [toit] INFO: <- OK
(411.844444) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(412.637977) [toit.scheduler] INFO: running job {job: persist_metrics}
(412.642821) [toit] INFO: -> AT+CSQ
(412.648380) [toit] INFO: <- +CSQ: 16,99
(412.651171) [toit] INFO: <- OK
(412.654099) [toit.metrics] INFO: persisting metrics
(412.743785) [toit] INFO: -> AT
(412.748287) [toit] INFO: <- OK
(413.752869) [toit] INFO: -> AT
(413.757245) [toit] INFO: <- OK
(414.761782) [toit] INFO: -> AT
(414.766146) [toit] INFO: <- OK
(415.770805) [toit] INFO: -> AT
(415.775083) [toit] INFO: <- OK
(416.779513) [toit] INFO: -> AT
(416.783798) [toit] INFO: <- OK
(417.788485) [toit] INFO: -> AT
(417.793151) [toit] INFO: <- OK
[gc @ 0x3ffcfa58* | soft limit reached (69660 >= 67626)]
[gc @ 0x3ffcfa58* | byte array allocation failed, length = 606 (heap)]
[gc @ 0x3ffcfa58* | heap: 68kb -> 32kb | external: 0kb -> 0kb | used: 221kb | free: 13kb->21kb (largest 8kb) 7.609ms]
(418.810543) [toit] INFO: -> AT
(418.814932) [toit] INFO: <- OK
(419.819622) [toit] INFO: -> AT
(419.823982) [toit] INFO: <- OK
(420.828385) [toit] INFO: -> AT
(420.832686) [toit] INFO: <- OK
(421.524986) [toit.scheduler] INFO: running job {job: poll_metric_flash_usage}
(421.837183) [toit] INFO: -> AT
(421.842278) [toit] INFO: <- OK
(421.875756) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(422.682318) [toit.scheduler] INFO: running job {job: persist_metrics}
(422.686998) [toit] INFO: -> AT+CSQ
(422.692817) [toit] INFO: <- +CSQ: 16,99
(422.695576) [toit] INFO: <- OK
(422.698490) [toit.metrics] INFO: persisting metrics
(422.847203) [toit] INFO: -> AT
(422.851645) [toit] INFO: <- OK
(423.856243) [toit] INFO: -> AT
(423.860739) [toit] INFO: <- OK
(424.866810) [toit] INFO: -> AT
(424.871216) [toit] INFO: <- OK
(425.875812) [toit] INFO: -> AT
(425.880147) [toit] INFO: <- OK
(426.884517) [toit] INFO: -> AT
(426.888780) [toit] INFO: <- OK
(427.893313) [toit] INFO: -> AT
(427.898088) [toit] INFO: <- OK
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | byte array allocation failed, length = 606 (heap)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 12kb) 7.612ms]
(428.914596) [toit] INFO: -> AT
(428.918919) [toit] INFO: <- OK
(429.923623) [toit] INFO: -> AT
(429.927915) [toit] INFO: <- OK
(430.932343) [toit] INFO: -> AT
(430.936690) [toit] INFO: <- OK
(431.906864) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(431.941388) [toit] INFO: -> AT
(431.946219) [toit] INFO: <- OK
(432.727275) [toit.scheduler] INFO: running job {job: persist_metrics}
(432.731713) [toit] INFO: -> AT+CSQ
(432.737694) [toit] INFO: <- +CSQ: 15,99
(432.740741) [toit] INFO: <- OK
(432.743715) [toit.metrics] INFO: persisting metrics
(432.952168) [toit] INFO: -> AT
(432.957332) [toit] INFO: <- OK
(433.962156) [toit] INFO: -> AT
(433.966685) [toit] INFO: <- OK
(434.971370) [toit] INFO: -> AT
(434.975771) [toit] INFO: <- OK
(435.980209) [toit] INFO: -> AT
(435.984535) [toit] INFO: <- OK
(436.988955) [toit] INFO: -> AT
(436.993219) [toit] INFO: <- OK
(437.999068) [toit] INFO: -> AT
(438.003872) [toit] INFO: <- OK
(439.008502) [toit] INFO: -> AT
(439.012762) [toit] INFO: <- OK
(440.017192) [toit] INFO: -> AT
(440.021422) [toit] INFO: <- OK
(441.026047) [toit] INFO: -> AT
(441.030266) [toit] INFO: <- OK
(441.937972) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.631ms]
(442.034743) [toit] INFO: -> AT
(442.039658) [toit] INFO: <- OK
(442.788382) [toit.scheduler] INFO: running job {job: persist_metrics}
(442.793090) [toit] INFO: -> AT+CSQ
(442.799371) [toit] INFO: <- +CSQ: 15,99
(442.802186) [toit] INFO: <- OK
(442.805108) [toit.metrics] INFO: persisting metrics
(442.958048) [toit] INFO: <- +SQNSRING: 1
(442.960590) [toit] INFO: <- [URC] +SQNSRING [1]
(442.981128) [toit] INFO: -> AT+SQNSI=1
(442.988488) [toit] INFO: <- +SQNSI: 1,3531,2671,47,0
(442.991272) [toit] INFO: <- OK
(443.013709) [toit] INFO: -> AT+SQNSRECV=1,1500
(443.019297) [toit] INFO: <- +SQNSRECV: <custom>
(443.022129) [toit] INFO: <- OK
(443.044504) [toit] INFO: -> AT+SQNSI=1
(443.050500) [toit] INFO: <- +SQNSI: 1,3531,2671,0,0
(443.053562) [toit] INFO: <- OK
(444.058560) [toit] INFO: -> AT
(444.063019) [toit] INFO: <- OK
(445.067654) [toit] INFO: -> AT
(445.072081) [toit] INFO: <- OK
(446.076438) [toit] INFO: -> AT
(446.080928) [toit] INFO: <- OK
(447.085545) [toit] INFO: -> AT
(447.090050) [toit] INFO: <- OK
(448.094405) [toit] INFO: -> AT
(448.099359) [toit] INFO: <- OK
(449.103921) [toit] INFO: -> AT
(449.108239) [toit] INFO: <- OK
(450.112883) [toit] INFO: -> AT
(450.117232) [toit] INFO: <- OK
(451.121610) [toit] INFO: -> AT
(451.126217) [toit] INFO: <- OK
(451.979726) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.630ms]
(452.139618) [toit] INFO: -> AT
(452.144504) [toit] INFO: <- OK
(452.834283) [toit.scheduler] INFO: running job {job: persist_metrics}
(452.839065) [toit] INFO: -> AT+CSQ
(452.844756) [toit] INFO: <- +CSQ: 16,99
(452.847529) [toit] INFO: <- OK
(452.850525) [toit.metrics] INFO: persisting metrics
(453.150387) [toit] INFO: -> AT
(453.155572) [toit] INFO: <- OK
(454.160477) [toit] INFO: -> AT
(454.164826) [toit] INFO: <- OK
(455.169323) [toit] INFO: -> AT
(455.173634) [toit] INFO: <- OK
(456.178777) [toit] INFO: -> AT
(456.183001) [toit] INFO: <- OK
(457.187424) [toit] INFO: -> AT
(457.191704) [toit] INFO: <- OK
(458.196188) [toit] INFO: -> AT
(458.201000) [toit] INFO: <- OK
(459.205796) [toit] INFO: -> AT
(459.210130) [toit] INFO: <- OK
(460.214550) [toit] INFO: -> AT
(460.218769) [toit] INFO: <- OK
(461.223130) [toit] INFO: -> AT
(461.227450) [toit] INFO: <- OK
(462.013390) [toit.scheduler] INFO: running job {job: poll_metric_memory_profile}
(462.231912) [toit] INFO: -> AT
(462.236745) [toit] INFO: <- OK
(462.891560) [toit.scheduler] INFO: running job {job: persist_metrics}
[gc @ 0x3ffcfa58* | soft limit reached (65564 >= 61482)]
[gc @ 0x3ffcfa58* | heap: 64kb -> 32kb | external: 0kb -> 0kb | used: 213kb | free: 13kb->29kb (largest 16kb) 7.725ms]
(462.905248) [toit] INFO: -> AT+CSQ
(462.911318) [toit] INFO: <- +CSQ: 15,99
(462.914081) [toit] INFO: <- OK
(462.917015) [toit.metrics] INFO: persisting metrics
(463.242617) [toit] INFO: -> AT
(463.247791) [toit] INFO: <- OK