Tracking down non-numeric input error

sroof · 28 December 2020 19:45

I’m trying to track down these input errors errors that I’m getting every 2-10 minutes:
ERROR|input_controller.php|{"success": false, "message": "Format error, json value is not numeric"} for User: 1

I’m running 10.2.6 on a Raspberry Pi with a fresh install 2 weeks ago. All of my inputs are sent to emonPi thru the API via Python code I’ve written myself, so I’m sure I’ve got a badly formatted json value somewhere. The trouble is, I’ve got 50+ Inputs and even more Feeds. I’ve studied the Inputs and Feeds pages and can’t find the one(s) causing the error. Is there some way to learn more about the bad input, such as which node it’s on, or what the bad value actually is? Or some way to help pinpoint which Input is causing the error?

Bill.Thomson · 29 December 2020 01:43

This is the first thing that came to mind. It may not be what’s causing your problem, and if it’s not,
then if nothing else, you’ve eliminated one source.

There are two variants of the API that handle JSON. One handles “JSON-like” strings, the
other handles valid JSON strings. Here’s a screenshot of the emonCMS inputs/api page

borpin · 29 December 2020 22:03

What is the emoncms logging level, DEBUG?

sroof · 29 December 2020 23:00

My current logging level is WARN. Changing to DEBUG sounds promising - how do I make the change?

Robert.Wall · 30 December 2020 01:40

In emonCMS, via your browser, in Emonhub→Edit config

It’s near the top, it’s the first line that isn’t a comment.

sroof · 30 December 2020 02:07

Thanks Robert, but isn’t the EmonHub log different from the Emoncms Log? The error I’m trying to track are showing up in the Emoncms Log:

If I can learn how to change the Emoncms Log to a more detailed Log Level, it might help me identify which Input has the json format error.

borpin · 30 December 2020 07:32

No that is the emonhub log (what it says on the tin).

You need to edit the settings.ini file.

nano /var/www/emoncms/settings.ini

and set the level = 1 (INFO will give you what you need I hope).

sroof · 30 December 2020 15:10

Thanks Brian - I edited the settings.ini file as you instructed and now I see lots more INFO entries in the emoncms log. Still, the input with the bad json format still shows up with the same ERROR line as when the log level was set to 2. I don’t see information helping me pinpoint the source of the error. It would be great if the error line included the node, or the label, or some other identifiers. But I guess that with a json error these attributes cannot be determined. I don’t know if it’s practical, but it would be helpful if the log showed the malformed json input. I’ve since found and corrected the source of the json error, so I’m “error-free” for now. Thanks for your help and ideas Brian and Robert.

borpin · 30 December 2020 16:45

Post some of the log around that error.

Do you know which input you expect to see but don’t?

sroof · 4 January 2021 15:27

I’m getting json input errors again, but this time I know that Feed 68 is the problem because it’s recently become inactive. I changed log to level 2 INFO and here’s the log surrounding the error:

If I didn’t already know that Feed 68 was the problem, I don’t see anything in the log that points to Feed 68 being the problem. It would be really helpful if the log showed more details about the json input error, such as which feed is causing it.

borpin · 4 January 2021 15:29

Can you please post as text and not an image.

When posting code or bash output, please put in 3 ‘backticks’ (found at the top left of the keyboard normally) on a line on their own, then the code, then 3 more backticks on a line following the code.

    ```
    code
    ```

If it is something like php you can add a language identifier that after the first 3 backticks so ```php

borpin · 4 January 2021 15:35

I mistakenly said this was INFO. Info is 2, Debug is 1 - you need debug set.

[Edit]
Can you also post where this input is coming from, The Raw JSON being sent to emoncms, and the debug log of the sender, please?

Can you check the value sent is not in quotes - numeric values in JSON should not be quoted.

Robert.Wall · 4 January 2021 16:25

If you don’t want the default markup, then you can label it thus
```text
Text not marked up
```

sroof · 4 January 2021 16:33

First, let me repeat that I’m asking if there are clues in the emoncms.log that indicate which feedid is causing an error (if not, then I’m requesting that if possible, future versions allow the emoncms.log to show more detail for errors). Specifically it would be really helpful if the log identified the feed causing an error. My challenge was trying to figure out which of my 170 feeds was causing the json error. Once I identified which feed was causing the error, I quickly fixed my Python code that sends the json string to emoncms. But simply identifying which feed was causing the error took a fair bit of time.

In settings.ini I’m not seeing a DEBUG mode:

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

level = 1 give the most detail. Here’s a portion of the emoncms.log containing the ERROR. Am I missing something that indicates which feedid is causing the error?

2021-01-04 15:34:37.901|INFO|feed_model.php|EngineClass() Autoloaded new instance of 'PHPFina'.
2021-01-04 15:34:38.085|INFO|feed_model.php|get_timevalue() calling VIRTUAL lastvalue 169
2021-01-04 15:34:38.086|INFO|feed_model.php|EngineClass() Autoloaded new instance of 'VirtualFeed'.
2021-01-04 15:34:38.090|INFO|process_processlist.php|source_feed_data_time() feedid=159 start=1609774.478 end=1609774.478 len=0 int=0 cnt=1 value=0 took=0.00073099136352539
2021-01-04 15:34:38.099|INFO|feed_model.php|get_timevalue() calling VIRTUAL lastvalue 181
2021-01-04 15:34:38.103|INFO|process_processlist.php|source_feed_data_time() feedid=160 start=1609774.478 end=1609774.478 len=0 int=0 cnt=1 value=1340 took=0.00072813034057617
2021-01-04 15:34:38.104|INFO|feed_model.php|get_timevalue() calling VIRTUAL lastvalue 182
2021-01-04 15:34:38.107|INFO|process_processlist.php|source_feed_data_time() feedid=173 start=1609774.478 end=1609774.478 len=0 int=0 cnt=1 value=6810 took=0.00073504447937012
2021-01-04 15:34:38.108|INFO|feed_model.php|get_timevalue() calling VIRTUAL lastvalue 183
2021-01-04 15:34:38.112|INFO|process_processlist.php|source_feed_data_time() feedid=173 start=1609774.478 end=1609774.478 len=0 int=0 cnt=1 value=6810 took=0.0007321834564209
2021-01-04 15:34:42.882|INFO|index.php|feed/list.json
2021-01-04 15:34:42.897|INFO|feed_model.php|EngineClass() Autoloaded new instance of 'PHPFina'.
2021-01-04 15:34:43.096|INFO|feed_model.php|get_timevalue() calling VIRTUAL lastvalue 169
2021-01-04 15:34:43.097|INFO|feed_model.php|EngineClass() Autoloaded new instance of 'VirtualFeed'.
2021-01-04 15:34:43.100|INFO|process_processlist.php|source_feed_data_time() feedid=159 start=1609774.483 end=1609774.483 len=0 int=0 cnt=1 value=0 took=0.00073504447937012
2021-01-04 15:34:43.109|INFO|feed_model.php|get_timevalue() calling VIRTUAL lastvalue 181
2021-01-04 15:34:43.113|INFO|process_processlist.php|source_feed_data_time() feedid=160 start=1609774.483 end=1609774.483 len=0 int=0 cnt=1 value=1340 took=0.00069904327392578
2021-01-04 15:34:43.114|INFO|feed_model.php|get_timevalue() calling VIRTUAL lastvalue 182
2021-01-04 15:34:43.117|INFO|process_processlist.php|source_feed_data_time() feedid=173 start=1609774.483 end=1609774.483 len=0 int=0 cnt=1 value=6810 took=0.00071287155151367
2021-01-04 15:34:43.119|INFO|feed_model.php|get_timevalue() calling VIRTUAL lastvalue 183
2021-01-04 15:34:43.122|INFO|process_processlist.php|source_feed_data_time() feedid=173 start=1609774.483 end=1609774.483 len=0 int=0 cnt=1 value=6810 took=0.00072693824768066
2021-01-04 15:34:47.879|INFO|index.php|feed/list.json
2021-01-04 15:34:47.894|INFO|feed_model.php|EngineClass() Autoloaded new instance of 'PHPFina'.
2021-01-04 15:34:48.072|INFO|feed_model.php|get_timevalue() calling VIRTUAL lastvalue 169
2021-01-04 15:34:48.072|INFO|feed_model.php|EngineClass() Autoloaded new instance of 'VirtualFeed'.
2021-01-04 15:34:48.076|INFO|process_processlist.php|source_feed_data_time() feedid=159 start=1609774.488 end=1609774.488 len=0 int=0 cnt=1 value=0 took=0.00076508522033691
2021-01-04 15:34:48.085|INFO|feed_model.php|get_timevalue() calling VIRTUAL lastvalue 181
2021-01-04 15:34:48.089|INFO|process_processlist.php|source_feed_data_time() feedid=160 start=1609774.488 end=1609774.488 len=0 int=0 cnt=1 value=1340 took=0.00094890594482422
2021-01-04 15:34:48.090|INFO|feed_model.php|get_timevalue() calling VIRTUAL lastvalue 182
2021-01-04 15:34:48.094|INFO|process_processlist.php|source_feed_data_time() feedid=173 start=1609774.488 end=1609774.488 len=0 int=0 cnt=1 value=6810 took=0.00073909759521484
2021-01-04 15:34:48.095|INFO|feed_model.php|get_timevalue() calling VIRTUAL lastvalue 183
2021-01-04 15:34:48.098|INFO|process_processlist.php|source_feed_data_time() feedid=173 start=1609774.488 end=1609774.488 len=0 int=0 cnt=1 value=6810 took=0.00078010559082031
2021-01-04 15:34:48.536|INFO|index.php|input/post
2021-01-04 15:34:48.543|INFO|index.php|Valid time in seconds used 1609774488
2021-01-04 15:34:48.544|ERROR|input_controller.php|{"success": false, "message": "Format error, json value is not numeric"} for User: 1
2021-01-04 15:34:49.460|INFO|index.php|input/post.json
2021-01-04 15:34:49.472|INFO|index.php|Valid time in seconds used 1609774489
2021-01-04 15:34:49.500|INFO|feed_model.php|insert_data() feedid=110 updatetime=1609774489 feedtime=1609774489 value=28.23 arg=
2021-01-04 15:34:49.501|INFO|feed_model.php|EngineClass() Autoloaded new instance of 'RedisBuffer'.
2021-01-04 15:34:49.503|INFO|feed_model.php|insert_data() feedid=111 updatetime=1609774489 feedtime=1609774489 value=1.03 arg=
2021-01-04 15:34:49.506|INFO|feed_model.php|insert_data() feedid=115 updatetime=1609774489 feedtime=1609774489 value=27.2 arg=
2021-01-04 15:34:49.508|INFO|feed_model.php|insert_data() feedid=112 updatetime=1609774489 feedtime=1609774489 value=25.49 arg=
2021-01-04 15:34:49.510|INFO|feed_model.php|insert_data() feedid=113 updatetime=1609774489 feedtime=1609774489 value=1.15 arg=
2021-01-04 15:34:49.512|INFO|feed_model.php|insert_data() feedid=114 updatetime=1609774489 feedtime=1609774489 value=0.57 arg=
2021-01-04 15:34:49.513|INFO|feed_model.php|insert_data() feedid=122 updatetime=1609774489 feedtime=1609774489 value=0.66 arg=
2021-01-04 15:34:49.515|INFO|feed_model.php|insert_data() feedid=123 updatetime=1609774489 feedtime=1609774489 value=0.08 arg=
2021-01-04 15:34:49.516|INFO|feed_model.php|insert_data() feedid=124 updatetime=1609774489 feedtime=1609774489 value=0.02 arg=
2021-01-04 15:34:49.518|INFO|feed_model.php|insert_data() feedid=125 updatetime=1609774489 feedtime=1609774489 value=0.26 arg=

borpin · 4 January 2021 19:17

Ah, OK my bad.

Agreed. If you want to suggest some changes to the code feel free to submit a PR.

pb66 · 4 January 2021 22:47

You are quite right that more info is needed in the log messages, the user id was added by me nearly 3 years ago as I had a similar problem, however I had numerous user accounts with only a few feeds each so adding the user id was enough for my needs at the time and quite easy to do, adding more detail might not be as easy I fear.

borpin · 5 January 2021 07:20

It’s one of those things, you only discover what info you need in debug when you need it .

I did the same (added debug code) when trying to track down an issue a while back.