Bug 1540926 - cockpit wizard fails to parse the output of the json callback
Summary: cockpit wizard fails to parse the output of the json callback
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: cockpit-ovirt
Classification: oVirt
Component: Hosted Engine
Version: 0.11.7
Hardware: Unspecified
OS: Unspecified
medium
medium
Target Milestone: ovirt-4.2.2
: 0.11.12
Assignee: Phillip Bailey
QA Contact: Yihui Zhao
URL:
Whiteboard:
: 1543040 (view as bug list)
Depends On: 1548958
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-02-01 10:51 UTC by Simone Tiraboschi
Modified: 2018-03-29 11:09 UTC (History)
13 users (show)

Fixed In Version: cockpit-ovirt-0.11.12-0.1
Clone Of:
Environment:
Last Closed: 2018-03-29 11:09:29 UTC
oVirt Team: Integration
Embargoed:
rule-engine: ovirt-4.2+
rule-engine: exception+
sbonazzo: devel_ack+
yzhao: testing_ack+


Attachments (Terms of Use)
issue (247.41 KB, image/png)
2018-02-01 10:51 UTC, Simone Tiraboschi
no flags Details
/tmp/out.json (34.59 KB, text/plain)
2018-02-02 06:11 UTC, Yihui Zhao
no flags Details
console_isue.png (197.87 KB, image/png)
2018-02-02 06:12 UTC, Yihui Zhao
no flags Details


Links
System ID Private Priority Status Summary Last Updated
oVirt gerrit 87370 0 ovirt-4.2 MERGED [ansible] wizard: do a better job parsing the JSON output 2018-02-20 17:45:53 UTC
oVirt gerrit 87982 0 ovirt-4.2 MERGED [ansible] wizard: do a better job parsing the JSON output 2018-02-20 17:45:59 UTC

Description Simone Tiraboschi 2018-02-01 10:51:01 UTC
Created attachment 1389445 [details]
issue

Description of problem:
cockpit wizard fails to parse the output of the json callback.
See the attached screenshot.

Version-Release number of selected component (if applicable):
0.11.7

How reproducible:
?

Steps to Reproduce:
1. Try deploying hosted-engine from cockpit and monitor the developer console
2.
3.

Actual results:
Uncaught Error: Read of /tmp/out.json failed to complete.

Expected results:
No read issue

Additional info:

Comment 1 Phillip Bailey 2018-02-01 12:11:41 UTC
Can you provide the contents of /tmp/out.json? Since the last version, I've added more error handling around the JSON parsing to avoid issues like this, but I'd like to see what it's choking on.

Comment 2 Yihui Zhao 2018-02-02 06:09:30 UTC
Can reproduce.

Test version:
cockpit-ovirt-dashboard-0.11.9-0.1.el7ev.noarch

Comment 3 Yihui Zhao 2018-02-02 06:11:16 UTC
Created attachment 1389926 [details]
/tmp/out.json

Comment 4 Yihui Zhao 2018-02-02 06:12:04 UTC
Created attachment 1389927 [details]
console_isue.png

Comment 5 Yihui Zhao 2018-02-02 06:13:47 UTC
Phillip, 
I attached the out.json file(https://bugzilla.redhat.com/attachment.cgi?id=1389926), and tested with the latest version: cockpit-ovirt-dashboard-0.11.9-0.1.el7ev.noarch

Comment 6 Ryan Barry 2018-02-06 23:18:38 UTC
There are multiple problems here.

The attached file isn't valid JSON. Each line is, but not the whole. This is more of a problem for anything which actually expects to read it as JSON.

It's not enough to do:

with open(OTOPI_CALLBACK_OF, 'w') as _fd:
  for f in foo_list:
    json.djump(payload, _fd)
    _fd.write('\n')
    _fd.flush()

Frankly, this is only appropriate for streaming over WebSockets, which we are not doing.

Using `tail -f` in cockpit is also not sufficient, even with a flush. The file can disappear from under this, leading to a `tail` pointing at a file handle, with no backing file left on the disk.

It would be better to use cockpit.file.watch(), and trim the output down to the last line.

Additionally, lines like:

{"OVEHOSTED_AC/body": "create_local_vm: {'stderr_lines': [], u'changed': True, u'end': u'2018-02-02 00:33:51.052192', u'stdout': u'\\nStarting install...\\nDomain creation completed.', u'cmd': [u'virt-install', u'-n', u'HostedEngineLocal', u'--os-variant', u'rhel7', u'--virt-type', u'kvm', u'--memory', u'4096', u'--vcpus', u'4', u'--network', u'network=default,mac=00:16:3E:6A:7A:F9,model=virtio', u'--disk', u'/var/tmp/localvmTRJEku/images/d73f231b-d1ec-43bd-bf4f-622cd3d4f1f5/55387735-bcd9-4eb6-89dc-d5a576b151ed', u'--import', u'--disk', u'path=/var/tmp/localvmTRJEku/seed.iso,device=cdrom', u'--noautoconsole', u'--rng', u'/dev/random', u'--graphics', u'vnc', u'--video', u'vga', u'--sound', u'none', u'--controller', u'usb,model=none', u'--memballoon', u'none', u'--boot', u'hd,menu=off', u'--clock', u'kvmclock_present=yes'], 'failed': False, u'delta': u'0:00:02.165299', u'stderr': u'', u'rc': 0, 'stdout_lines': [u'', u'Starting install...', u'Domain creation completed.'], u'start': u'2018-02-02 00:33:48.886893'}", "OVEHOSTED_AC/type": "OVEHOSTED_AC/debug"}

Are a huge headache. `tail -f` is following and we're sending it to cockpit, which is then trying .split(/\n/) to try to pull the lines off. We can improve the regexp here to not split on "\\n", but why is raw JSON output present in here at all?

I'd suggest that the entire JSON output from the ansible flow needs to be reworked, but we can try to find a workaround in cockpit for now.

Comment 7 Ryan Barry 2018-02-07 15:47:18 UTC
*** Bug 1543040 has been marked as a duplicate of this bug. ***

Comment 8 Simone Tiraboschi 2018-02-07 16:28:01 UTC
(In reply to Ryan Barry from comment #6)
> The attached file isn't valid JSON. Each line is, but not the whole. This is
> more of a problem for anything which actually expects to read it as JSON.

Yes, right.
We don't want to wait for the end of the playbook execution (it can last up to 20 minutes) to get all the results in a single shot but we need a stream of events to keep the user updated each time a task concludes.
So a newline-delimited JSON stream over a file appeared a good option; see: http://jsonlines.org/
https://www.npmjs.com/package/jsonlines

> but why is raw JSON output
> present in here at all?

Just to have something more structured than parsing plain text ansible output on console. 

> I'd suggest that the entire JSON output from the ansible flow needs to be
> reworked, but we can try to find a workaround in cockpit for now.

That callback was specifically deployed for otopi, other ready to use callback plugin are already available:
https://github.com/ansible/ansible/tree/devel/lib/ansible/plugins/callback

Comment 9 Ryan Barry 2018-02-07 16:38:21 UTC
I'll look at the parsers to see if there's something more suitable.

It's likely that splitting on /\n$/ would be enough by itself, so we don't hit newlines from otopi, but I'm also of the opinion that it would be better to add a "lines" field in the output and let otopi/python handle the splitting instead of dumping raw output into a field.

As it is, newlines are not a sufficient delimiter. Probably with EOL added, but I suspect jsonlines was never intended for this sort of use case

Comment 10 Simone Tiraboschi 2018-02-07 18:18:42 UTC
(In reply to Ryan Barry from comment #9)
> It's likely that splitting on /\n$/ would be enough by itself, so we don't
> hit newlines from otopi, but I'm also of the opinion that it would be better
> to add a "lines" field in the output and let otopi/python handle the
> splitting instead of dumping raw output into a field.

That one is a strong ansible limit and we cannot do that much there: we are executing engine-setup on the engine VM via ansible as well and engine-setup writes a lot of stuff.
In ansible there no way to get the output of a long running command line by line as a stream in real time but you we just going to get all the output just at the end in 'stdout' and 'stderr' raw field.

Also the relevant callback methods are going to be called just at task end (and the whole engine-setup is just a single task for us) and not every n seconds.

See for instance:
https://github.com/ansible/ansible/issues/3887
https://github.com/ansible/ansible/issues/4870
https://github.com/ansible/ansible/issues/11233

> but I suspect jsonlines was never intended for this sort of use case

Why?
http://jsonlines.org/ says "It's also a flexible format for passing messages between cooperating processes." which is exactly what we are doing.

Comment 11 Simone Tiraboschi 2018-02-07 18:27:26 UTC
Ryan, another relevant thing.
Now Didi completed a second callback called 2_ovirt_logger.py that produces reasonable, complete and well filtered logs.
Can you please add it as well in callback list on ansible-playbook invocation?

Comment 12 Ryan Barry 2018-02-07 18:35:14 UTC
(In reply to Simone Tiraboschi from comment #10)
> (In reply to Ryan Barry from comment #9)
> > It's likely that splitting on /\n$/ would be enough by itself, so we don't
> > hit newlines from otopi, but I'm also of the opinion that it would be better
> > to add a "lines" field in the output and let otopi/python handle the
> > splitting instead of dumping raw output into a field.
> 
> That one is a strong ansible limit and we cannot do that much there: we are
> executing engine-setup on the engine VM via ansible as well and engine-setup
> writes a lot of stuff.
> In ansible there no way to get the output of a long running command line by
> line as a stream in real time but you we just going to get all the output
> just at the end in 'stdout' and 'stderr' raw field.

I mean, I understand this, but it still seems that we could do a little processing before a flat json.dump(...) in order to avoid having newlines in a  field.

Since this is handled by 1_otopi_json, it shouldn't be too much. I'd be happy to contribute a patch.

This is the request, I suppose. 

> > but I suspect jsonlines was never intended for this sort of use case
> 
> Why?
> http://jsonlines.org/ says "It's also a flexible format for passing messages
> between cooperating processes." which is exactly what we are doing.

That's true, in the same sense that websockets do the same thing.

The format itself is fine, but since we are not actually using the jsonlines npm package to parse this, and instead are naively trying "string.split(/\n/)", we're not exactly adhering to it.

To say that it wasn't intended for this purpose is basically to say:

jsonlines is fine, but it was likely never intended that a consumer could just watch the end of a file and split(/\n/) to get individual lines out.

Either a stronger regexp (which what I suspect the jsonlines libraries are doing themselves anyway) or using the actual jsonlines package.

To avoid adding another package to ovirt-engine-nodejs-modules, I'll try better regular expressions first.

(In reply to Simone Tiraboschi from comment #11)

> Ryan, another relevant thing.
> Now Didi completed a second callback called 2_ovirt_logger.py that produces
> reasonable, complete and well filtered logs.
> Can you please add it as well in callback list on ansible-playbook
> invocation?

Definitely.

Comment 13 Simone Tiraboschi 2018-02-07 19:01:40 UTC
(In reply to Ryan Barry from comment #12)
> I mean, I understand this, but it still seems that we could do a little
> processing before a flat json.dump(...) in order to avoid having newlines in
> a  field.
> 
> Since this is handled by 1_otopi_json, it shouldn't be too much. I'd be
> happy to contribute a patch.
> 
> This is the request, I suppose. 

Oh we already have it:
in ansible command module results we have 'stdout' and 'stdout_lines'; the first one is a long string with \n, the second one is an array of lines.
The content is the same.

Basically you are talking about suppressing 'stdout' and 'stderr' in command and shell modules and keeping just 'stdout_lines' and 'stderr_lines'.

> jsonlines is fine, but it was likely never intended that a consumer could
> just watch the end of a file and split(/\n/) to get individual lines out.

I'd suggest to do it on the fly line by line to keep the user updated.

> Definitely.

Thanks

Comment 14 Ryan Barry 2018-02-07 19:06:48 UTC
(In reply to Simone Tiraboschi from comment #13)
> (In reply to Ryan Barry from comment #12)
> > I mean, I understand this, but it still seems that we could do a little
> > processing before a flat json.dump(...) in order to avoid having newlines in
> > a  field.
> > 
> > Since this is handled by 1_otopi_json, it shouldn't be too much. I'd be
> > happy to contribute a patch.
> > 
> > This is the request, I suppose. 
> 
> Oh we already have it:
> in ansible command module results we have 'stdout' and 'stdout_lines'; the
> first one is a long string with \n, the second one is an array of lines.
> The content is the same.

Oh, perfect. It would be ideal to simply block 'stdout' from going to the JSON, but I can work around this.

> 
> Basically you are talking about suppressing 'stdout' and 'stderr' in command
> and shell modules and keeping just 'stdout_lines' and 'stderr_lines'.
> 
> > jsonlines is fine, but it was likely never intended that a consumer could
> > just watch the end of a file and split(/\n/) to get individual lines out.
> 
> I'd suggest to do it on the fly line by line to keep the user updated.

That's still the idea, just with smarter parsing so we don't accidentally split on 'stdout' then try to parse the remainder as invalid JSON.

> 
> > Definitely.
> 
> Thanks

Comment 15 Yihui Zhao 2018-03-02 06:01:00 UTC
Tested cockpit-ovirt-0.11.14-0.1 on RHEL7.4 without this issue.

Test version:
Red Hat Enterprise Linux Server 7.4 Beta (Maipo)
ovirt-hosted-engine-ha-2.2.6-1.el7ev.noarch
cockpit-ovirt-dashboard-0.11.14-0.1.el7ev.noarch
ovirt-hosted-engine-setup-2.2.11-1.el7ev.noarch
cockpit-storaged-158-1.el7.noarch
cockpit-bridge-157-1.el7.x86_64
cockpit-157-1.el7.x86_64
cockpit-dashboard-158-1.el7.x86_64
cockpit-ws-157-1.el7.x86_64
cockpit-system-157-1.el7.noarch
rhvm-appliance-4.2-20180202.0.el7.noarch


So, I will change the bug's status to verified.

Comment 16 Sandro Bonazzola 2018-03-29 11:09:29 UTC
This bugzilla is included in oVirt 4.2.2 release, published on March 28th 2018.

Since the problem described in this bug report should be
resolved in oVirt 4.2.2 release, it has been closed with a resolution of CURRENT RELEASE.

If the solution does not work for you, please open a new bug report.


Note You need to log in before you can comment on or make changes to this bug.