Community
OpenEnergyMonitor

Community

EmonPi stopped logging inputs

Hi All,

I’ve recently received a new EmonPi from the shop, it is my first. I also have an EmonTX.

I set the system up for the first time last night, the system was reading inputs well. I configured the system through the web interface to also log to emoncms.org. and perfrormed the full update. All looked good! Graphs were happening, data was logging. Neat.

However… after a reboot initiated from the webinterface it now looks like the inputs are not reading on either the base or the tx:

EmonCMS.org:

This appears in the EmonCMS log:

Stack trace:
#0 /var/www/emoncms/Modules/process/process_processlist.php(987): exceptions_error_handler(8, 'Undefined index...', '/var/www/emoncm...', 987, Array)
#1 /var/www/emoncms/Modules/process/process_model.php(71): Process_ProcessList->power_to_kwh('7', 1573641169, '30', NULL, Object(Process))
#2 /var/www/emoncms/Modules/process/process_model.php(122): Process->__call('power_to_kwh', Array)
#3 /var/www/emoncms/scripts/services/emoncms_mqtt/emoncms_mqtt.php(383): Process->input(1573641169, '30', '1:1,4:2,4:7,1:8')
#4 [internal function]: message(Object(Mosquitto\Message))
#5 /var/www/emoncms/scripts/services/emoncms_mqtt/emoncms_mqtt.php(137): Mosquitto\Client->loop()
#6 {main}

Appreciate any pointers for where I should be looking to track down the problem?

Thanks!

Dave.

Can you click on the button ‘copy as markdown’ next to ‘Server Information’ and paste here (no further formatting required)

Sure, thanks!

Server Information

Server Information

Services

  • emonhub :- Active Running
  • emoncms_mqtt :- Active Running
  • feedwriter :- Active Running - sleep 300s 0 feed points pending write
  • service-runner :- Active Running
  • emonPiLCD :- Active Running
  • redis-server :- Active Running
  • mosquitto :- Active Running
  • demandshaper :- Active Running

Emoncms

  • Version :- low-write 10.1.11
  • Modules :- Administration | App v2.0.9 | Backup v2.1.7 | EmonHub Config v2.0.4 | Dashboard v2.0.5 | DemandShaper v1.1.0 | Device v2.0.3 | EventProcesses | Feed | Graph v2.0.6 | Input | Postprocess v2.1.2 | CoreProcess | Schedule | Network Setup v1.0.0 | sync | Time | User | Visualisation | WiFi v2.0.2
  • Git :-

Server

  • OS :- Linux 4.19.75-v7+
  • Host :- emonpi | emonpi | (192.168.1.46)
  • Date :- 2019-11-13 20:58:39 UTC
  • Uptime :- 20:58:39 up 1:08, 0 users, load average: 0.06, 0.03, 0.03

Memory

  • RAM :- Used: 18.51%
    • Total :- 975.62 MB
    • Used :- 180.57 MB
    • Free :- 795.05 MB
  • Swap :- Used: 0.00%
    • Total :- 100 MB
    • Used :- 0 B
    • Free :- 100 MB
      Write Load Period

Disk

  • / :- Used: 46.53%
    • Total :- 3.92 GB
    • Used :- 1.83 GB
    • Free :- 1.9 GB
    • Write Load :- 687.53 B/s (56 mins)
  • /var/opt/emoncms :- Used: 0.04%
    • Total :- 9.98 GB
    • Used :- 3.8 MB
    • Free :- 9.47 GB
    • Write Load :- 0 B/s (56 mins)
  • /boot :- Used: 20.55%
    • Total :- 252.05 MB
    • Used :- 51.79 MB
    • Free :- 200.26 MB
    • Write Load :- 0 B/s (56 mins)
  • /var/log :- Used: 2.20%
    • Total :- 50 MB
    • Used :- 1.1 MB
    • Free :- 48.9 MB
    • Write Load :- n/a

HTTP

  • Server :- Apache/2.4.38 (Raspbian) HTTP/1.1 CGI/1.1 80

MySQL

  • Version :- 5.5.5-10.3.17-MariaDB-0+deb10u1
  • Host :- localhost:6379 (127.0.0.1)
  • Date :- 2019-11-13 20:58:39 (UTC 00:00‌​)
  • Stats :- Uptime: 4082 Threads: 12 Questions: 7010 Slow queries: 0 Opens: 46 Flush tables: 1 Open tables: 40 Queries per second avg: 1.717

Redis

  • Version :-
    • Redis Server :- 5.0.3
    • PHP Redis :- 5.0.2
  • Host :- localhost:6379
  • Size :- 77 keys (849.68K)
  • Uptime :- 0 days

MQTT Server

  • Version :- Mosquitto 1.5.7
  • Host :- localhost:1883 (127.0.0.1)

PHP

  • Version :- 7.3.9-1~deb10u1 (Zend Version 3.3.9)
  • Modules :- apache2handler | calendar v7.3.9-1~deb10u1 | Core v7.3.9-1~deb10u1 | ctype v7.3.9-1~deb10u1 | curl v7.3.9-1~deb10u1 | date v7.3.9-1~deb10u1 | dom v20031129 | exif v7.3.9-1~deb10u1 | fileinfo v7.3.9-1~deb10u1 | filter v7.3.9-1~deb10u1 | ftp v7.3.9-1~deb10u1 | gd v7.3.9-1~deb10u1 | gettext v7.3.9-1~deb10u1 | hash v7.3.9-1~deb10u1 | iconv v7.3.9-1~deb10u1 | json v1.7.0 | libxml v7.3.9-1~deb10u1 | mbstring v7.3.9-1~deb10u1 | mosquitto v0.4.0 | mysqli v7.3.9-1~deb10u1 | mysqlnd vmysqlnd 5.0.12-dev - 20150407 - $Id: 7cc7cc96e675f6d72e5cf0f267f48e167c2abb23 $ | openssl v7.3.9-1~deb10u1 | pcre v7.3.9-1~deb10u1 | PDO v7.3.9-1~deb10u1 | pdo_mysql v7.3.9-1~deb10u1 | Phar v7.3.9-1~deb10u1 | posix v7.3.9-1~deb10u1 | readline v7.3.9-1~deb10u1 | redis v5.0.2 | Reflection v7.3.9-1~deb10u1 | session v7.3.9-1~deb10u1 | shmop v7.3.9-1~deb10u1 | SimpleXML v7.3.9-1~deb10u1 | sockets v7.3.9-1~deb10u1 | sodium v7.3.9-1~deb10u1 | SPL v7.3.9-1~deb10u1 | standard v7.3.9-1~deb10u1 | sysvmsg v7.3.9-1~deb10u1 | sysvsem v7.3.9-1~deb10u1 | sysvshm v7.3.9-1~deb10u1 | tokenizer v7.3.9-1~deb10u1 | wddx v7.3.9-1~deb10u1 | xml v7.3.9-1~deb10u1 | xmlreader v7.3.9-1~deb10u1 | xmlwriter v7.3.9-1~deb10u1 | xsl v7.3.9-1~deb10u1 | Zend OPcache v7.3.9-1~deb10u1 | zlib v7.3.9-1~deb10u1

Pi

  • Model :- Raspberry Pi 3 Model B Rev 1.2 - 1GB (Sony UK)

  • Serial num. :- 9EB4422

  • Temperature :- 51.00°C - 50.5°C

  • emonpiRelease :- emonSD-17Oct19

  • File-system :- read-write

Client Information

Client Information

HTTP

  • Browser :- Mozilla/5.0 (Linux; Android 9; SM-N960F) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/78.0.3904.96 Mobile Safari/537.36
  • Language :- en-AU,en;q=0.9

Window

  • Size :- 412 x 718

Screen

  • Resolution :- 412 x 846

Have you tried a second boot?

Is there anything else in the emoncms.log? If you SSH in, and edit the settings file nano /var/www/emoncms/settings.ini and look for log and set the level to 1.

[log]
; Log Level: 1=INFO, 2=WARN, 3=ERROR
level = 1

Thanks Brian:

Have rebooted and power cycled the base a few times now. Most recently when changing the emoncms log level as per your note.

This is the /var/log/emoncms/emoncms.log including the latest boot:

2019-11-14 06:46:19.634|INFO|index.php|device/list.json
2019-11-14 06:46:19.660|INFO|index.php|input/list.json
2019-11-14 06:46:24.636|INFO|index.php|device/list.json
2019-11-14 06:46:24.666|INFO|index.php|input/list.json
2019-11-14 06:46:29.637|INFO|index.php|device/list.json
2019-11-14 06:46:29.664|INFO|index.php|input/list.json
2019-11-14 06:46:58.997|INFO|feedwriter.php|Starting feedwriter script
2019-11-14 06:46:59.004|INFO|demandshaper_run.php|Starting demandshaper service
2019-11-14 06:46:58.997|INFO|emoncms_mqtt.php|Starting MQTT Input script
2019-11-14 06:46:59.106|INFO|feedwriter.php|Buffered feed writer daemon started with sleep 300s...
2019-11-14 06:46:59.132|INFO|feed_model.php|EngineClass() Autoloaded new instance of 'RedisBuffer'.
2019-11-14 06:46:59.235|WARN|emoncms_mqtt.php|Not connected, retrying connection
2019-11-14 06:46:59.246|WARN|emoncms_mqtt.php|Connecting to MQTT server: Connection Accepted.: code: 0
2019-11-14 06:46:59.247|INFO|emoncms_mqtt.php|Subscribed to: emon/# ID - 1
2019-11-14 06:46:59.258|INFO|emoncms_mqtt.php|Callback subscribed to topic: 
2019-11-14 06:47:35.467|INFO|index.php|admin/view
2019-11-14 06:47:35.521|INFO|rememberme_model.php|login
2019-11-14 06:47:35.533|INFO|rememberme_model.php|findTriplet TRIPLET_FOUND
2019-11-14 06:47:35.534|INFO|rememberme_model.php|cleanTriplet success
2019-11-14 06:47:35.536|INFO|rememberme_model.php|setCookie: 1|0fd3bbf2983a80c385cd058eaa558f5d|1165b3e05b56ff4608208d9f991e2f1c 1581490055
2019-11-14 06:47:35.547|ERROR|index.php|Not Admin|admin/view
2019-11-14 06:47:35.642|INFO|user_model.php|get_preferences()|Empty User preferences
2019-11-14 06:47:35.660|INFO|user_model.php|get_preferences()|Empty User preferences
2019-11-14 06:47:41.765|INFO|index.php|user/logout
2019-11-14 06:47:41.794|INFO|rememberme_model.php|cookieIsValid
2019-11-14 06:47:41.797|INFO|rememberme_model.php|findTriplet TRIPLET_FOUND
2019-11-14 06:47:41.809|INFO|user_model.php|logout
2019-11-14 06:47:41.809|INFO|rememberme_model.php|clearCookie
2019-11-14 06:47:41.810|INFO|rememberme_model.php|setCookie:  1565938061
2019-11-14 06:47:41.810|INFO|rememberme_model.php|clearCookie call to cleanTriplet
2019-11-14 06:47:41.812|INFO|rememberme_model.php|cleanTriplet success
2019-11-14 06:47:41.978|INFO|rememberme_model.php|login
2019-11-14 06:47:41.978|INFO|rememberme_model.php|getCookieValues: not present
2019-11-14 06:47:42.023|INFO|user_model.php|get_preferences()|Empty User preferences
2019-11-14 06:47:42.038|INFO|user_model.php|get_preferences()|Empty User preferences
2019-11-14 06:47:47.691|INFO|index.php|user/login.json
2019-11-14 06:47:47.720|INFO|rememberme_model.php|login
2019-11-14 06:47:47.721|INFO|rememberme_model.php|getCookieValues: not present
2019-11-14 06:47:47.726|INFO|rememberme_model.php|createCookie
2019-11-14 06:47:47.728|INFO|rememberme_model.php|setCookie: 1|1eac5037992044685dd8842663eb8069|8fb7795dd8e0f8c14ad767e1672142f9 1581490067
2019-11-14 06:47:47.878|INFO|index.php|feed/list
2019-11-14 06:47:48.016|INFO|user_model.php|get_preferences()|Empty User preferences
2019-11-14 06:47:48.027|INFO|user_model.php|get_preferences()|Empty User preferences
2019-11-14 06:47:48.315|INFO|index.php|feed/list.json
2019-11-14 06:47:48.321|INFO|index.php|process/list.json
2019-11-14 06:47:48.330|INFO|index.php|schedule/list.json
2019-11-14 06:47:48.334|INFO|index.php|input/list.json
2019-11-14 06:47:48.359|INFO|feed_model.php|EngineClass() Autoloaded new instance of 'PHPFina'.
2019-11-14 06:47:48.359|INFO|PHPFina.php|lastvalue() 1
2019-11-14 06:47:48.367|INFO|PHPFina.php|lastvalue() 2
2019-11-14 06:47:48.371|INFO|PHPFina.php|lastvalue() 3
2019-11-14 06:47:48.374|INFO|PHPFina.php|lastvalue() 4
2019-11-14 06:47:48.377|INFO|PHPFina.php|lastvalue() 5
2019-11-14 06:47:48.380|INFO|PHPFina.php|lastvalue() 6
2019-11-14 06:47:48.383|INFO|PHPFina.php|lastvalue() 7
2019-11-14 06:47:48.386|INFO|PHPFina.php|lastvalue() 8
2019-11-14 06:47:48.389|INFO|PHPFina.php|lastvalue() 9
2019-11-14 06:47:48.713|INFO|index.php|feed/list.json
2019-11-14 06:47:48.726|INFO|feed_model.php|EngineClass() Autoloaded new instance of 'PHPFina'.
2019-11-14 06:47:52.833|INFO|index.php|config
2019-11-14 06:47:52.869|INFO|user_model.php|get_preferences()|Empty User preferences
2019-11-14 06:47:52.888|INFO|user_model.php|get_preferences()|Empty User preferences
2019-11-14 06:47:53.134|INFO|index.php|config/get
2019-11-14 06:47:53.134|INFO|index.php|config/getemonhublog
2019-11-14 06:47:54.145|INFO|index.php|config/getemonhublog
2019-11-14 06:47:55.149|INFO|index.php|config/getemonhublog
2019-11-14 06:47:56.147|INFO|index.php|config/getemonhublog
2019-11-14 06:47:57.154|INFO|index.php|config/getemonhublog
2019-11-14 06:47:58.136|INFO|index.php|config/getemonhublog
2019-11-14 06:47:59.137|INFO|index.php|config/getemonhublog
2019-11-14 06:48:00.148|INFO|index.php|config/getemonhublog
2019-11-14 06:48:01.147|INFO|index.php|config/getemonhublog
2019-11-14 06:48:02.148|INFO|index.php|config/getemonhublog
2019-11-14 06:48:03.145|INFO|index.php|config/getemonhublog
2019-11-14 06:48:04.145|INFO|index.php|config/getemonhublog
2019-11-14 06:48:05.147|INFO|index.php|config/getemonhublog
2019-11-14 06:48:06.144|INFO|index.php|config/getemonhublog
2019-11-14 06:48:07.146|INFO|index.php|config/getemonhublog
2019-11-14 06:48:08.148|INFO|index.php|config/getemonhublog
2019-11-14 06:48:09.121|INFO|demandshaper_run.php|Starting demandshaper service
2019-11-14 06:48:09.143|INFO|demandshaper_model.php|Saved to redis only
2019-11-14 06:48:09.646|INFO|index.php|config/getemonhublog
2019-11-14 06:48:10.627|INFO|index.php|config/getemonhublog
2019-11-14 06:48:11.629|INFO|index.php|config/getemonhublog
2019-11-14 06:48:12.639|INFO|index.php|config/getemonhublog
2019-11-14 06:48:13.637|INFO|index.php|config/getemonhublog
2019-11-14 06:48:14.650|INFO|index.php|config/getemonhublog
2019-11-14 06:48:15.161|INFO|index.php|config/getemonhublog
2019-11-14 06:48:16.170|INFO|index.php|config/getemonhublog
2019-11-14 06:48:17.146|INFO|index.php|config/getemonhublog
2019-11-14 06:48:18.150|INFO|index.php|config/getemonhublog
2019-11-14 06:48:18.501|INFO|index.php|admin/view
2019-11-14 06:48:19.145|INFO|index.php|config/getemonhublog
2019-11-14 06:48:19.614|INFO|user_model.php|get_preferences()|Empty User preferences
2019-11-14 06:48:19.630|INFO|user_model.php|get_preferences()|Empty User preferences
2019-11-14 06:48:20.014|INFO|index.php|admin/getlog
2019-11-14 06:48:20.017|INFO|index.php|admin/emonpi/getupdatelog
2019-11-14 06:48:20.021|INFO|index.php|feed/buffersize.json
2019-11-14 06:48:32.388|INFO|index.php|admin/downloadlog
2019-11-14 06:49:00.233|INFO|demandshaper_model.php|Saved to redis only
2019-11-14 06:50:00.333|INFO|demandshaper_model.php|Saved to redis only
2019-11-14 06:51:00.434|INFO|demandshaper_model.php|Saved to redis only
2019-11-14 06:52:00.541|INFO|demandshaper_model.php|Saved to redis only
2019-11-14 06:52:00.835|INFO|emoncms_mqtt.php|0 Messages processed in last 5 minutes
2019-11-14 06:52:24.419|INFO|index.php|admin/getlog
2019-11-14 06:52:24.887|INFO|index.php|admin/getlog
2019-11-14 06:52:25.400|INFO|index.php|admin/getlog
2019-11-14 06:52:25.896|INFO|index.php|admin/getlog
2019-11-14 06:52:26.396|INFO|index.php|admin/getlog
2019-11-14 06:52:26.899|INFO|index.php|admin/getlog
2019-11-14 06:52:27.396|INFO|index.php|admin/getlog
2019-11-14 06:52:27.899|INFO|index.php|admin/getlog
2019-11-14 06:52:28.396|INFO|index.php|admin/getlog
2019-11-14 06:52:56.842|INFO|index.php|admin/downloadlog

I deleted all the feeds to see if that made a difference. Unfortunately no change.

There is also this on the emonhub log:

Note the “2019-11-14 07:02:04,073 WARNING MainThread Device communication error - check settings”. Not sure if this is meaningful.

2019-11-14 07:02:02,066 INFO     MainThread EmonHub emonHub emon-pi variant v2.1.2
2019-11-14 07:02:02,067 INFO     MainThread Opening hub...
2019-11-14 07:02:02,067 INFO     MainThread Logging level set to DEBUG
2019-11-14 07:02:02,068 INFO     MainThread Creating EmonHubJeeInterfacer 'RFM2Pi' 
2019-11-14 07:02:02,070 DEBUG    MainThread Opening serial port: /dev/ttyAMA0 @ 38400 bits/s
2019-11-14 07:02:04,073 WARNING  MainThread Device communication error - check settings
2019-11-14 07:02:04,074 INFO     MainThread Setting RFM2Pi frequency: 433 (4b)
2019-11-14 07:02:05,076 INFO     MainThread Setting RFM2Pi group: 210 (210g)
2019-11-14 07:02:06,079 INFO     MainThread Setting RFM2Pi quiet: 0 (0q)
2019-11-14 07:02:07,081 INFO     MainThread Setting RFM2Pi baseid: 5 (5i)
2019-11-14 07:02:08,083 INFO     MainThread Setting RFM2Pi calibration: 230V (1p)
2019-11-14 07:02:09,085 DEBUG    MainThread Setting RFM2Pi subchannels: ['ToRFM12']
2019-11-14 07:02:09,086 DEBUG    MainThread Setting RFM2Pi pubchannels: ['ToEmonCMS']
2019-11-14 07:02:09,087 INFO     MainThread Creating EmonHubMqttInterfacer 'MQTT' 
2019-11-14 07:02:09,090 DEBUG    MainThread Setting MQTT subchannels: ['ToEmonCMS']
2019-11-14 07:02:09,091 DEBUG    MainThread Setting MQTT pubchannels: ['ToRFM12']
2019-11-14 07:02:09,091 INFO     MainThread Setting MQTT nodevar_format_enable: 1
2019-11-14 07:02:09,092 INFO     MainThread Setting MQTT node_format_enable: 1
2019-11-14 07:02:09,092 INFO     MainThread Setting MQTT nodevar_format_basetopic: emon/
2019-11-14 07:02:09,093 INFO     MainThread Creating EmonHubEmoncmsHTTPInterfacer 'emoncmsorg' 
2019-11-14 07:02:09,095 DEBUG    MainThread Setting emoncmsorg subchannels: ['ToEmonCMS']
2019-11-14 07:02:09,096 DEBUG    MainThread Setting emoncmsorg pubchannels: ['ToRFM12']
2019-11-14 07:02:09,096 INFO     MainThread Setting emoncmsorg url: https://emoncms.org
2019-11-14 07:02:09,096 INFO     MainThread Setting emoncmsorg senddata: 1
2019-11-14 07:02:09,097 INFO     MainThread Setting emoncmsorg apikey: set
2019-11-14 07:02:09,097 INFO     MainThread Setting emoncmsorg sendstatus: 1

Found the issue.

At some point during the upgrades I have updated the firmware. I must have selected an incorrect firmware type in the web interface as I just re-performed the update using the emonpi image and the inputs started receiving again. Problem solved!

Thanks for your help Brian!

1 Like