Error retrieving version?

[hollie]

Hello,

I just noticed the following error in my MisterHouse log:

06/24/14 18:00:01  Download page retrieved
Error in user code shown in short form (set show_all_errors=yes in mh.private.init to get in full form each time):
malformed JSON string, neither tag, array, object, number, string or atom, at character offset 0 (before "(end of string)") at (eval 137) line 2641.
 at mh line 31.
    main::__ANON__('malformed JSON string, neither tag, array, object, number, st...') called at (eval 137) line 2641
    main::mh_release_loopcode() called at (eval 137) line 5937
    main::loop_code called at (eval 6330607) line 1
    eval '&loop_code' called at mh line 2901
    main::eval_user_code_loop called at mh line 1530
    main::check_for_action called at mh line 3303
    main::monitor_commands called at mh line 6741
Display call with tk disabled (-tk 0).  Text=6 eval errors in mh_release out of 10 allowed before disable

Could this be related to recent changes in parsing the version info?
Is there anybody who is noticing the same error?

MisterHouse info (running a relatively recent master):
Version: develop-ref Build 277 (129f4f4)
Modified: 2014-05-16 19:20:09 +0200
OS: darwin
Perl: 5.18.2

Best regards,
Lieven.

[JaredF]

I'm not seeing this on mine (I'm running latest master, but there haven't been any changes to any of the version coding since Build 277 anyway...):

06/24/2014 09:45:13  Running: Check Misterhouse version
06/24/2014 09:45:13  Retrieving download page
06/24/2014 09:45:13  Checking version...
06/24/2014 09:45:14  Download page retrieved
06/24/2014 09:45:14  Retrieving download date page
normal: Checking version date...
06/24/2014 09:45:14  FUNCTION: set_volume_pre_hook
normal: (chime.wav)
06/24/2014 09:45:14  FUNCTION: set_volume_pre_hook
06/24/2014 09:45:14  Setting wav volume to 100
06/24/2014 09:45:14  Previous wav volume was
06/24/2014 09:45:14  running: aplay -D plughw:CARD=SB,DEV=0 -q /usr/local/bin/misterhouse/private/sounds/chime.wav
06/24/2014 09:45:14  web_hook_callback:
06/24/2014 09:45:15  Download date page retrieved
normal: You are running the development branch, it has no version releases.

Check this file: $config_parms{data_dir}/web/mh_download.html and see if it looks like properly formed JSON.

[hollie]

Hmm, the file looks OK to me.

I have verified this is actually the file that was downloaded at 18:00. A copy of the file is here:
https://gist.github.com/hollie/0b875fbe945332a62139

[JaredF]

I just diffed my file with yours and they are identical. I was hoping that it might have been something simple like a file with a HTTP error instead of the JSON file. I also ran the file through JSONlint and the file passed as perfectly valid JSON...

Is you JSON perl module up to date? An environmental cause is my best guess since both our MH versions as well as the parsed JSON files are identical. To narrow down the issue, you could try running the same file through a simple perl script run directly from the command line to see if the same error is thrown outside of MH.

[hollie]

Hey Jared,

there is a JSON module that comes with MisterHouse under lib/site. This is version 2.27 and as far as I know MisterHouse prefers the included modules over the system-installed ones so AFAIK we should be using the same version of the module too.

Or am I missing something?

In the mean time I found back in the logs I had the same error on 8/06, on 14/06 and now today. So it is not a one-off.

[hollie]

I added the mh.private.ini parameter for full log, giving me this when I trigger the version command:

06/24/14 21:28:11 : malformed JSON string, neither tag, array, object, number, string or atom, at character offset 0 (before "(end of string)") at (eval 137) line 2641.
 at mh line 31.
    main::__ANON__('malformed JSON string, neither tag, array, object, number, st...') called at (eval 137) line 2641
    main::mh_release_loopcode() called at (eval 137) line 5937
    main::loop_code called at (eval 1106) line 1
Line 2636:
Line 2637:
Line 2638:  if (done_now $p_mhdl_page) {
Line 2639:      my @html = file_read($mhdl_file);
Line 2640:      print_log("Download page retrieved");
Line 2641:      my $json = decode_json( @html );
Line 2642:      my ($mhdl_date_url, $maj, $min);
Line 2643:      foreach (@{$json}) {
Line 2644:          next unless $_->{name} =~ m/^v(\d+)\.(\d+)/;
Line 2645:          next unless (($1 > $maj) or ($1 == $maj and $2 > $min));
Line 2646:          $maj = $1;
normal: Error found in user code.  Check the error log.

So definitely JSON module related. I'll see if I can narrow this further down.

[JaredF]

You are right--it is using the internal JSON module in lib/site/JSON/PP.pm

Do you see the error every single time you run the trigger manually or are you only seeing it scattered in past log messages? Perhaps those happened to be times when GitHub was down for maintenance and an empty response was returned?

Looking at the PP.pm file, the error you are seeing should only be thrown if the data passed to PP_decode_json is completely empty or a NULL reference. It would throw a more specific error if it were being passed poorly-formed or completely non-JSON data...

[krkeegan]

This at character offset 0 might mean that we are dealing with a
character encoding issue. Almost like the start of file data is wrong.
Perhaps we have a platform distinction going on here? I am thinking
something similar to the difference in line endings between various
platforms. Maybe get_url produces slightly different results on different
platforms?

On Tue, Jun 24, 2014 at 12:33 PM, Lieven Hollevoet <notifications@github.com

wrote:

I added the mh.private.ini parameter for full log, giving me this when I
trigger the version command:

06/24/14 21:28:11 : malformed JSON string, neither tag, array, object, number, string or atom, at character offset 0 (before "(end of string)") at (eval 137) line 2641.
at mh line 31.
main::ANON('malformed JSON string, neither tag, array, object, number, st...') called at (eval 137) line 2641
main::mh_release_loopcode() called at (eval 137) line 5937
main::loop_code called at (eval 1106) line 1
Line 2636:
Line 2637:
Line 2638: if (done_now $p_mhdl_page) {
Line 2639: my @html = file_read($mhdl_file);
Line 2640: print_log("Download page retrieved");
Line 2641: my $json = decode_json( @html );
Line 2642: my ($mhdl_date_url, $maj, $min);
Line 2643: foreach (@{$json}) {
Line 2644: next unless $_->{name} =~ m/^v(\d+).(\d+)/;
Line 2645: next unless (($1 > $maj) or ($1 == $maj and $2 > $min));
Line 2646: $maj = $1;
normal: Error found in user code. Check the error log.

So definitely JSON module related. I'll see if I can narrow this further.

—
Reply to this email directly or view it on GitHub
#420 (comment).

[JaredF]

Scratch that--it looks like they have that error listed several times throughout the module; I was only looking at the first occurrence.

[JaredF]

@krkeegan, agreed; I can't think of any other possible cause other than a different perl version perhaps?

In any case, if someone can figure out a good way to run files through these functions and the compare the outputs, I would be glad to submit my results.

Until today, I didn't have the mh_release code running, so it's possible that I may eventually get some of these as well if it's only occurring every so often.

[krkeegan]

You can force the check to run through the following links on the web
interface:

Mr. House -> Browse MisterHouse -> "Check Misterhouse version"

I can click it any number of times without issue.

On Tue, Jun 24, 2014 at 12:54 PM, Jared Fernandez notifications@github.com
wrote:

@krkeegan https://github.com/krkeegan, agreed; I can't think of any
other possible cause other than a different perl version perhaps?

In any case, if someone can figure out a good way to run files through
these functions and the compare the outputs, I would be glad to submit my
results.

Until today, I didn't have the mh_release code running, so it's possible
that I may eventually get some of these as well if it's only occurring
every so often.

—
Reply to this email directly or view it on GitHub
#420 (comment).

[hollie]

@krkeegan Yes, that is the way I triggered it to get the 'extended' error report I pasted earlier. I will look into writing a small test script that just reads the file and calls the decode_json() function so that I can experiment with the included JSON module and a recent one. But that won't be for today.

[hollie]

I finally had some time to explore this further. Compared to the previous error report I updated MisterHouse to the latest master.

I examined the error logs further and noticed that I get a recurring daily error log on the version check.

So I wrote this small script to test if I could trigger the error when running the code manually:

#! /usr/bin/env/perl

use lib qw(../../../mh_master/lib/site);

use JSON::PP;
use File::Slurp;

print "Using module version: $JSON::PP::VERSION\n";

my $filename = $ARGV[0];
my @html = read_file($filename);
my $json = decode_json(@html);

I can't trigger the problem with this example script. So I'm suspecting something is wrong with the file_read routine that is used in the version check script (I was using the File::Slurp read_file routine).

I'll look further into this when I find time to explore it further. A quick grep on 'file_read' shows that this function is used widely in MisterHouse.

[hollie]

After realizing that there was a small difference between the code in my example script and the mh_release.pl code I was able to get my script to return the same error as MisterHouse does when checking the version.

If in the script that is listed in the previous comment I change

use JSON:PP;

to

use JSON qw(decode_json);

then the example script errors out with the same error.

Obviously, when I change the use line in mh_release.pl to 'use JSON:PP;' then the script works fine.

I don't know if it is OK to change the mh_release.pl script like this because I don't know why the original author did write the 'use' statement the way it is written now. What do the others think? Should I create a pull request for this fix (that apparently only occurs on my system/OS)?

[hollie]

Pull request that fixes this has been merged into master.

[hollie]

Pull request that fixes this is: #463