Bug 1286116 - "--since-time" does not work for oc logs
"--since-time" does not work for oc logs
Status: CLOSED CURRENTRELEASE
Product: OpenShift Origin
Classification: Red Hat
Component: Pod (Show other bugs)
3.x
Unspecified Unspecified
medium Severity medium
: ---
: ---
Assigned To: Jordan Liggitt
Jianwei Hou
:
Depends On:
Blocks: 1462997
  Show dependency treegraph
 
Reported: 2015-11-27 06:16 EST by Xingxing Xia
Modified: 2017-06-19 16:40 EDT (History)
5 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
: 1462997 (view as bug list)
Environment:
Last Closed: 2016-09-19 09:50:07 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Xingxing Xia 2015-11-27 06:16:52 EST
Description of problem:
"--since-time" does not work for oc logs, it outputs error.


Version-Release number of selected component (if applicable):
openshift/oc v1.1-233-g5145e05
kubernetes v1.1.0-origin-1107-g4c8e6f4

How reproducible:
Always

Steps to Reproduce:
1. Start openshift, oc login, create a project
2. Create a pod
3. Check the log with "--since-time"
$ oc logs pod/<pod name> --since-time "2015-11-27T09:54:55.266317390Z"


Actual results:
3.
Error from server: Unable to convert <nil> to conversion.structAdaptor{typ:(*reflect.rtype)(0x2a2b080), ptr:(unsafe.Pointer)(0xc212a6f480), flag:0xd9}

Expected results:
3. The command should succeed.


Additional info:
Furthermore, it is better to directly give examples of time format in the help info rather than give RFC3339 to let customer to find it. (You can find it in http://tools.ietf.org/html/rfc3339#section-5.8)
Comment 1 Xingxing Xia 2015-12-02 01:36:57 EST
And negative test shows strange message:
$ oc logs pod/<pod_name> --since-time="#@234"
error: parsing time "#@234" as "2006-01-02T15:04:05Z07:00": cannot parse "#@234" as "2006"

Why 'as "2006-01-02T15:04:05Z07:00"'? There must be something wrong.
Comment 2 Michail Kargakis 2015-12-02 05:17:13 EST
This is a known issue upstream (https://github.com/kubernetes/kubernetes/issues/17561) and is actually part of a bigger problem (broken conversion from inline structs to query parameters: https://github.com/openshift/origin/pull/5396#issuecomment-151142232).
Comment 4 Xingxing Xia 2016-02-17 04:17:32 EST
In latest versions:
openshift/oc v1.1.2-285-gb39b3d8
kubernetes v1.2.0-origin

The test result changes to:
$ oc logs pod/doublecontainers --since-time="2015-11-27T09:54:10Z"
panic: reflect: NumField of non-struct type

goroutine 1 [running]:
reflect.(*rtype).NumField(0x1a4b920, 0x1a37401)
	/usr/lib/golang/src/reflect/type.go:657 +0x7a
k8s.io/kubernetes/pkg/conversion/queryparams.convertStruct(0xc20854a630, 0x7f9085b1d0e8, 0x1a4b920, 0x1a37460, 0xc208539ee0, 0xd9)
	/go/src/github.com/openshift/origin/Godeps/_workspace/src/k8s.io/kubernetes/pkg/conversion/queryparams/convert.go:121 +0x4e
k8s.io/kubernetes/pkg/conversion/queryparams.convertStruct(0xc20854a630, 0x7f9085b1d0e8, 0x199c1a0, 0x199c1a0, 0xc20854e3c0, 0xd9)
	/go/src/github.com/openshift/origin/Godeps/_workspace/src/k8s.io/kubernetes/pkg/conversion/queryparams/convert.go:145 +0x3d1
k8s.io/kubernetes/pkg/conversion/queryparams.Convert(0x18f6a20, 0xc20854e3c0, 0x18f6a20, 0x0, 0x0)

......Much output stuff skipped......

goroutine 15 [syscall]:
os/signal.loop()
	/usr/lib/golang/src/os/signal/signal_unix.go:21 +0x1f
created by os/signal.init·1
	/usr/lib/golang/src/os/signal/signal_unix.go:27 +0x35

goroutine 35 [runnable]:
net/http.(*persistConn).readLoop(0xc2082834a0)
	/usr/lib/golang/src/net/http/transport.go:928 +0x9ce
created by net/http.(*Transport).dialConn
	/usr/lib/golang/src/net/http/transport.go:660 +0xc9f

goroutine 36 [select]:
net/http.(*persistConn).writeLoop(0xc2082834a0)
	/usr/lib/golang/src/net/http/transport.go:945 +0x41d
created by net/http.(*Transport).dialConn
	/usr/lib/golang/src/net/http/transport.go:661 +0xcbc
Comment 5 David Eads 2016-02-17 07:44:17 EST
This pull should fix the problem, but its waiting on the current kube rebase to complete: https://github.com/openshift/origin/pull/7353.
Comment 6 Jordan Liggitt 2016-02-18 00:49:34 EST
fix in https://github.com/openshift/origin/pull/7394
Comment 7 Xingxing Xia 2016-02-21 21:58:23 EST
In latest version:
openshift/oc v1.1.3-170-g14b50fd
kubernetes v1.2.0-alpha.7-703-gbc4550d

Actual test result shows "--since-time" works.
Steps:
1. Start openshift, oc login, create a project
2. Create a pod (fro new app)
$ oc new-app -f origin/examples/sample-app/application-template-stibuild.json
$ oc get pod
NAME                        READY     STATUS      RESTARTS   AGE
database-1-01c97            1/1       Running     0          18m
...
3. Check the log with "--since-time"
1> $ oc logs pod/database-1-01c97 --timestamps
...
2016-02-22T02:32:59.626737885Z 160222  2:32:59  InnoDB: Starting shutdown...
2016-02-22T02:33:01.253689614Z 160222  2:33:01  InnoDB: Shutdown completed; log sequence number 1595675
...
2016-02-22T02:33:01.628302794Z ---> 02:33:01     Cleaning up environment variables MYSQL_USER, MYSQL_PASSWORD, MYSQL_DATABASE and MYSQL_ROOT_PASSWORD ...
...
2> $ oc logs pod/database-1-01c97   --timestamps --since-time="2016-02-22T02:33:01Z"
2016-02-22T02:33:01.253689614Z 160222  2:33:01  InnoDB: Shutdown completed; log sequence number 1595675
...
2016-02-22T02:33:01.628302794Z ---> 02:33:01     Cleaning up environment variables MYSQL_USER, MYSQL_PASSWORD, MYSQL_DATABASE and MYSQL_ROOT_PASSWORD ...
...

In step 3.2, it only outputs logs newer than 2016-02-22T02:33:01Z, which is we expect.
Comment 8 Xingxing Xia 2016-02-21 22:15:25 EST
But still have 2 minor issues:
1. If using preciser time value for --since-time, the result is:
$ oc logs pod/database-1-01c97   --timestamps --since-time="2016-02-22T02:33:01.628302794Z"
It seems to ignore .628302794, and the output is:
2016-02-22T02:33:01.253689614Z 160222  2:33:01  InnoDB: Shutdown completed; log sequence number 1595675
...

This issue is very minor. Would you plan to fix this?

2. The issue in comment 1 still exists. It always mentions "2006", why "2006"?

Before move bug to VERIFIED, I'd like to know the response for the 2 issues.
Thank you.
Comment 9 Jordan Liggitt 2016-02-21 22:30:17 EST
1. No, subsecond precision is not supported by RFC3339 (which is the format used by the API and the command-line to represent time)

2. RFC3339 is expressed in terms of an example date string:
RFC3339     = "2006-01-02T15:04:05Z07:00"
https://golang.org/pkg/time/#pkg-constants

When it attempts to parse the input text, it is doing so using that format string.

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