Bug 1123935 - node-proxy writes an invalid timestamp to logs when node is in UTC TZ
Summary: node-proxy writes an invalid timestamp to logs when node is in UTC TZ
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: OpenShift Online
Classification: Red Hat
Component: Containers
Version: 2.x
Hardware: Unspecified
OS: Unspecified
medium
medium
Target Milestone: ---
: 2.x
Assignee: Rajat Chopra
QA Contact: libra bugs
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2014-07-28 16:43 UTC by Jhon Honce
Modified: 2015-05-14 23:37 UTC (History)
5 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2014-10-10 00:49:49 UTC


Attachments (Terms of Use)

Description Jhon Honce 2014-07-28 16:43:23 UTC
Description of problem:
node-proxy writes an invalid timestamp to logs when node is in UTC TZ

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


How reproducible:
always

Steps to Reproduce:
1. config node for UTC timezone
2. run oo-last-access
3.

Actual results:
    /usr/sbin/oo-last-access:110:in `strptime': invalid date (ArgumentError)
            from /usr/sbin/oo-last-access:110:in `block (3 levels) in parse_log'
            from /usr/sbin/oo-last-access:99:in `each'
            from /usr/sbin/oo-last-access:99:in `block (2 levels) in parse_log'
            from /usr/sbin/oo-last-access:98:in `popen'
            from /usr/sbin/oo-last-access:98:in `block in parse_log'
            from /usr/sbin/oo-last-access:97:in `each'
            from /usr/sbin/oo-last-access:97:in `parse_log'
            from /usr/sbin/oo-last-access:167:in `block in <main>'
            from /usr/sbin/oo-last-access:149:in `call'
            from /usr/sbin/oo-last-access:149:in `single_instance'
            from /usr/sbin/oo-last-access:155:in `<main>'


Expected results:
Log is successfully parsed.

Additional info:
Note: Ruby expects a +- in front of TZ field.

[root@node2 ~]# cat /var/log/node-web-proxy/websockets.log
 
179.98.105.155 meteor-caruccio.getup.io - - [25/Jul/2014:19:11:25 0000] "GET /sockjs/838/ad4l8fch/websocket HTTP/1.1" 1000 4005 "-" "Websocket RFC-6455/13" (822085ms) -
179.98.105.155 meteor-caruccio.getup.io - - [25/Jul/2014:21:28:15 0000] "GET /sockjs/132/4quo29hi/websocket HTTP/1.1" 1000 5421 "-" "Websocket RFC-6455/13" (1046406ms) -
179.98.105.155 meteor-caruccio.getup.io - - [25/Jul/2014:22:38:57 0000] "GET /sockjs/428/o6tzauwl/websocket HTTP/1.1" 1000 1156 "-" "Websocket RFC-6455/13" (75346ms) -
179.98.105.155 meteor-caruccio.getup.io - - [26/Jul/2014:22:02:53 0000] "GET /sockjs/780/pvifap4p/websocket HTTP/1.1" 1000 1104 "-" "Websocket RFC-6455/13" (3375ms) -

Comment 1 Rajat Chopra 2014-07-29 19:19:41 UTC
Put in some debug messages to print memory information after each watchman plugin is invoked. The messages go in /var/log/messages and the debug mode can be enabled by setting an env var 'WATCHMAN_DEBUG' to true.

Hopefully we can narrow it down which plugin causes the leak.

https://github.com/openshift/origin-server/pull/5670

Comment 2 Rajat Chopra 2014-07-29 19:27:57 UTC
Wrong update in comment#1 above. Was meant for another bug. Pardon please.

Comment 3 Rajat Chopra 2014-07-30 06:08:35 UTC
The better option would be to fix nodejs Logger, but until that is found..
an alternate proposal for fix in https://github.com/openshift/origin-server/pull/5671

Comment 4 Meng Bo 2014-07-31 11:15:26 UTC
Checked on devenv-stage_937, issue has been fixed.

With UTC timezone set on node. Comment out the 4 lines in oo-last-access script, I can get the error as:

[root@ip-10-179-182-124 ~]# oo-last-access
/usr/sbin/oo-last-access:117:in `strptime': invalid date (ArgumentError)
        from /usr/sbin/oo-last-access:117:in `block (3 levels) in parse_log'
        from /usr/sbin/oo-last-access:100:in `each'
        from /usr/sbin/oo-last-access:100:in `block (2 levels) in parse_log'
        from /usr/sbin/oo-last-access:99:in `popen'
        from /usr/sbin/oo-last-access:99:in `block in parse_log'
        from /usr/sbin/oo-last-access:98:in `each'
        from /usr/sbin/oo-last-access:98:in `parse_log'
        from /usr/sbin/oo-last-access:173:in `block in <main>'
        from /usr/sbin/oo-last-access:155:in `call'
        from /usr/sbin/oo-last-access:155:in `single_instance'
        from /usr/sbin/oo-last-access:161:in `<main>'


With the fix patched:

[root@ip-10-179-182-124 ~]# oo-last-access
[root@ip-10-179-182-124 ~]# 


Move bug to verified.


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