Bug 1591118 - [crio] Event process failure error appears in atomic-openshift-node log
Summary: [crio] Event process failure error appears in atomic-openshift-node log
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: OpenShift Container Platform
Classification: Red Hat
Component: Containers
Version: 3.10.0
Hardware: Unspecified
OS: Unspecified
medium
medium
Target Milestone: ---
: 3.10.z
Assignee: Antonio Murdaca
QA Contact: Meng Bo
URL:
Whiteboard:
Depends On:
Blocks: 1591158
TreeView+ depends on / blocked
 
Reported: 2018-06-14 06:14 UTC by Meng Bo
Modified: 2020-09-20 12:46 UTC (History)
10 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
: 1591158 1690259 (view as bug list)
Environment:
Last Closed: 2019-04-09 23:40:43 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHBA-2019:0620 0 None None None 2019-04-09 23:40:52 UTC

Description Meng Bo 2018-06-14 06:14:39 UTC
Description of problem:
Tons of "invalid character 'c' looking for beginning of value" errors appear in node log when cluster running with crio.

Jun 13 23:58:12 ip-172-18-14-79.ec2.internal atomic-openshift-node[18924]: ERROR: logging before flag.Parse: W0613 23:58:12.971203   18924 manager.go:1178] Failed to process watch event {EventType:0 Name:/kubepods.slice/kubepods-besteffort.slice/kubepods-besteffort-pod2262d6c2_6f87_11e8_86dd_0eb037b2774e.slice/crio-b188fba45a612b6fd7cbb00dd6150e182e86ecef6f0447abd67210f08e2a456f.scope WatchSource:0}: invalid character 'c' looking for beginning of value
Jun 13 23:58:16 ip-172-18-14-79.ec2.internal atomic-openshift-node[18924]: ERROR: logging before flag.Parse: W0613 23:58:16.489277   18924 manager.go:1178] Failed to process watch event {EventType:0 Name:/kubepods.slice/kubepods-besteffort.slice/kubepods-besteffort-pod2262d6c2_6f87_11e8_86dd_0eb037b2774e.slice/crio-2cb7f38521db0cd9584b4d52c7d5e76e39aea96f226b7f4fadf811252e3c5e5a.scope WatchSource:0}: invalid character 'c' looking for beginning of value
Jun 13 23:59:40 ip-172-18-14-79.ec2.internal atomic-openshift-node[18924]: ERROR: logging before flag.Parse: W0613 23:59:40.225422   18924 manager.go:1178] Failed to process watch event {EventType:0 Name:/kubepods.slice/kubepods-besteffort.slice/kubepods-besteffort-pod5b7ccb19_6f87_11e8_86dd_0eb037b2774e.slice/crio-e6ccc38071c3b403accd153c11775f7fd933305f31b551d4b6c6597692ce777d.scope WatchSource:0}: invalid character 'c' looking for beginning of value
Jun 13 23:59:54 ip-172-18-14-79.ec2.internal atomic-openshift-node[18924]: ERROR: logging before flag.Parse: W0613 23:59:54.687828   18924 manager.go:1178] Failed to process watch event {EventType:0 Name:/kubepods.slice/kubepods-besteffort.slice/kubepods-besteffort-pod5b7ccb19_6f87_11e8_86dd_0eb037b2774e.slice/crio-ea3d01c5538a2b238bbdacf534aa30b77454cecde90d47c782a9e2c2722ae297.scope WatchSource:0}: invalid character 'c' looking for beginning of value


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

How reproducible:
v3.10.0-0.67.0

Steps to Reproduce:
1. Setup ocp cluster with crio
2. Check the node log
3.

Actual results:
Tons of "invalid character 'c' looking for beginning of value" errors

Expected results:
Should not have such error

Additional info:
There is no such problem on docker container env.

Comment 1 Antonio Murdaca 2018-06-14 08:04:16 UTC
Fix is here: https://github.com/kubernetes-incubator/cri-o/pull/1615

Comment 2 Antonio Murdaca 2018-06-14 10:02:39 UTC
that was not the fix, my bad, I'm working on one right now

Comment 3 Antonio Murdaca 2018-06-14 10:38:18 UTC
Fix here https://github.com/kubernetes-incubator/cri-o/pull/1616

Comment 4 Mrunal Patel 2018-06-19 17:48:04 UTC
This is fixed in crio 1.10.3

Comment 5 Mrunal Patel 2018-06-20 12:50:38 UTC
Can this be tested and moved to verified?

Comment 6 Peter Ruan 2018-06-20 17:26:00 UTC
still seeing the errors in the node logs with crio verison 1.10.3

[root@qe-pruan-auto-310-all-in-one-crio-preserve-merrn-1 ~]# crio --version
crio version 1.10.3
commit: "54383a69903e1b46526be3dbe0bea71b14f00e46-dirty"
[root@qe-pruan-auto-310-all-in-one-crio-preserve-merrn-1 ~]# journalctl -u atomic-openshift-node.service    | grep "Failed to process watch event"
Jun 18 16:30:00 qe-pruan-auto-310-all-in-one-crio-preserve-merrn-1 atomic-openshift-node[22829]: W0618 16:30:00.331301   22829 manager.go:1178] Failed to process watch event {EventType:0 Name:/kubepods.slice/kubepods-besteffort.slice/kubepods-besteffort-podf8ddfa563d27a7f9ca95644fe2f8cdd0.slice/crio-28263d9946f502dc7ed03ecb134d8f13f55b6cc3863aad0e3e4f42ea8bfcfc34.scope WatchSource:0}: invalid character 'c' looking for beginning of value
Jun 18 16:30:00 qe-pruan-auto-310-all-in-one-crio-preserve-merrn-1 atomic-openshift-node[22829]: W0618 16:30:00.333551   22829 manager.go:1178] Failed to process watch event {EventType:0 Name:/kubepods.slice/kubepods-besteffort.slice/kubepods-besteffort-pod83e9c11b241c6539016d50a962142eda.slice/crio-075774ac13d768cf7f4729bba748570a5eaa329ca63eae303417d28ffcfe494a.scope WatchSource:0}: invalid character 'c' looking for beginning of value

Comment 7 Antonio Murdaca 2018-06-21 07:59:01 UTC
Could you provide full cri-o log for the above run please?

Comment 8 Antonio Murdaca 2018-06-21 08:58:40 UTC
(In reply to Peter Ruan from comment #6)
> still seeing the errors in the node logs with crio verison 1.10.3
> 
> [root@qe-pruan-auto-310-all-in-one-crio-preserve-merrn-1 ~]# crio --version
> crio version 1.10.3
> commit: "54383a69903e1b46526be3dbe0bea71b14f00e46-dirty"
> [root@qe-pruan-auto-310-all-in-one-crio-preserve-merrn-1 ~]# journalctl -u
> atomic-openshift-node.service    | grep "Failed to process watch event"
> Jun 18 16:30:00 qe-pruan-auto-310-all-in-one-crio-preserve-merrn-1
> atomic-openshift-node[22829]: W0618 16:30:00.331301   22829 manager.go:1178]
> Failed to process watch event {EventType:0
> Name:/kubepods.slice/kubepods-besteffort.slice/kubepods-besteffort-
> podf8ddfa563d27a7f9ca95644fe2f8cdd0.slice/crio-
> 28263d9946f502dc7ed03ecb134d8f13f55b6cc3863aad0e3e4f42ea8bfcfc34.scope
> WatchSource:0}: invalid character 'c' looking for beginning of value
> Jun 18 16:30:00 qe-pruan-auto-310-all-in-one-crio-preserve-merrn-1
> atomic-openshift-node[22829]: W0618 16:30:00.333551   22829 manager.go:1178]
> Failed to process watch event {EventType:0
> Name:/kubepods.slice/kubepods-besteffort.slice/kubepods-besteffort-
> pod83e9c11b241c6539016d50a962142eda.slice/crio-
> 075774ac13d768cf7f4729bba748570a5eaa329ca63eae303417d28ffcfe494a.scope
> WatchSource:0}: invalid character 'c' looking for beginning of value

could you also provide access to the test machine?

Comment 9 Meng Bo 2018-06-21 11:05:48 UTC
Yeah, I can see the problem on OCP 3.10.2-1 and cri-o 1.10.3

Jun 21 17:25:40 ocp310-node2.bmeng.local atomic-openshift-node[1663]: ERROR: logging before flag.Parse: E0621 17:25:36.856474    1663 manager.go:1130] Failed to create existing container: /kubepods.slice/kubepods-burstable.slice/kubepods-burstable-pod32c61a68_6881_11e8_8add_525400c1455c.slice/crio-10cb6cd6ad5a692d5a7cd31ee355447ebda9d3d16026768ae4c4978ddf643e60.scope: invalid character 'c' looking for beginning of value
Jun 21 17:25:40 ocp310-node2.bmeng.local atomic-openshift-node[1663]: ERROR: logging before flag.Parse: E0621 17:25:36.857341    1663 manager.go:1130] Failed to create existing container: /kubepods.slice/kubepods-burstable.slice/kubepods-burstable-pod32c61a68_6881_11e8_8add_525400c1455c.slice/crio-60e955109ec274dc6b4d3e7237097e1eb106aa2e2255d94a2ae221b69b18873c.scope: invalid character 'c' looking for beginning of value

Comment 11 Antonio Murdaca 2018-06-25 14:44:50 UTC
Tentatively moving this to 3.10.z because I don't believe this is a blocker (though, we're still actively working on it!). The issue here is that cgroups show up earlier than cadvisor querying the CRI-O endpoint, resulting in that error in logs. Anyway, the next time cadvisor queries the CRI-O endpoing, everything is gonna be successful.

Comment 12 Antonio Murdaca 2018-08-27 13:50:01 UTC
can you re-test with latest openshift+crio? if it's not working could you please provide a test vm where I can reproduce myself? Thanks

Comment 13 Meng Bo 2018-08-29 05:59:37 UTC
I cannot see the ERRORs on ocp v3.10.34 with cri-o-1.10.6-1.rhaos3.10.git56d7d9a.el7.x86_64

Comment 14 Antonio Murdaca 2018-08-29 09:07:06 UTC
can you move to verified?

Comment 16 errata-xmlrpc 2019-04-09 23:40:43 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

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

https://access.redhat.com/errata/RHBA-2019:0620


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