EmonPi stopped logging inputs

David_Ford · 13 November 2019 20:29

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.

borpin · 13 November 2019 20:57

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

David_Ford · 13 November 2019 20:59

Sure, thanks!

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 :-
- URL :- GitHub - emoncms/emoncms: Web-app for processing, logging and visualising energy, temperature and other environmental data
- Branch :- * stable
- Describe :- 10.1.11

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

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

borpin · 13 November 2019 21:06

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

David_Ford · 14 November 2019 06:54

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

David_Ford · 14 November 2019 07:09

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

David_Ford · 14 November 2019 07:27

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!