Bug 967997

Summary: Not Readable tail log output to console
Product: OpenShift Online Reporter: Ihor <sp.titan>
Component: ImageAssignee: Dan Mace <dmace>
Status: CLOSED WONTFIX QA Contact: libra bugs <libra-bugs>
Severity: low Docs Contact:
Priority: unspecified    
Version: 2.xCC: bvarga, dmcphers, jkeck
Target Milestone: ---Keywords: SupportQuestion
Target Release: ---   
Hardware: i386   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2014-07-23 12:30:44 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
o_O none

Description Ihor 2013-05-28 18:27:52 UTC
Created attachment 754037 [details]
o_O

Description of problem: Not Readable tail log output in console


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

ihor@ihor-M50Vc:~$ sudo gem update rhc
[sudo] password for ihor: 
Updating installed gems
Nothing to update

How reproducible:
only need to run rhc tail -a rs
static tail(from file/*boot.log server.log) first ~20 lines have normal output.
live output is terrible, very not readable.
I still have this issue maybe 3 months.

Steps to Reproduce:
1. run rhc tail -a rs
2. rhc app restart -a rs
3. enjoy))

Actual results:
RESULT:
mysql-5.1 started
ihor@ihor-M50Vc:~$ rhc app restart -a rs
Password: ******
Unable to complete the requested operation due to: Node execution failure
(invalid exit code from node). If the problem persists
please contact Red Hat support..
Reference ID: 573490a0d90cb2000d10e2217843aba8
ihor@ihor-M50Vc:~$ rhc app start -a rs
Password: ******

RESULT:
rs started
ihor@ihor-M50Vc:~$ rhc app start -a rs
Password: ******

RESULT:
rs started
ihor@ihor-M50Vc:~$

ected.__DatatypeFactor
y
javax.xml.parsers.Doc
umentBuilderFactory =
__redirected.__Documen
tBuilderFa
ctory
javax.xml.parsers.SAXParserFactory = __redirected.__SAXParserFactory
javax.xml.
stream.XMLEventFactory =
__redirected.__XMLEvent
Factory
javax.xml.strea
m.XMLInputFactory = __redirected.__XMLInputFactory
javax.xml.stream.XMLOutputFactory =
__redirected.__XMLOutp
utFactory
javax.xml
.
transform.TransformerFactory
= __redirected.__Trans
formerFactory
javax.x
ml.validation.SchemaFac
tory:http://www.
w3.org/2001/XMLSchema = __re
directed.__SchemaFactory

javax.xml.xpath.XPath
Factory:http:/
/java.sun.com/jaxp/xpath/dom = __redirected.__XPathFacto
ry
jboss.home.dir =
/var/lib/openshift/512f7
6
d
34382ecafaf0002b8/jbossas-7/jbossas-7
jboss.host.name = ex-std-node86
jboss.modules.dir = /var/
l
ib/openshift/512f76d3438
2ecafaf0002b8/jbossas-
7/jbossas-7/modules
jboss.node.name = rs-eme
temunoy.rhcloud.com

jbos
s.qualified.host.name = ex-std-node86.prod.rhcloud.com
jboss.server.base.dir = /var/lib/o
penshift/512f76d3
4382ecafaf0002b8/jbos
sas-7/jbossas-7/stand
alone
jboss.server
.config.dir = /var/
lib/openshift/512f7
6d34382ecafaf0002b8/jbossas-7/jbossas-7/standalone/configuration
jboss.server.data.dir =
/var/lib/openshift/512f76d34382ecafaf0002b8/jbossas-7/jbossas-7/standalone/data
jboss.server.deploy.dir =
/var/lib/openshift/512f76d34382ecafaf0002b8/jbossas-7/jbossas-7/standalone/data/content
jboss.server.log.dir
= /var/lib/openshift
/512f76d34382ecafaf0
002b8/jbossas-7
/jbossas-7/standalone/lo
g
jboss.server.name =
ex-std-node86
jboss.s
e
rver.temp.dir =
/var/lib/openshift/512
f76d34382ecafaf0002
b8/jbossas-7/jbossas-7/
standalone/tmp
jgro
ups.bin
d_addr =
127.12.40.129
line.
sepa
rator =

logging
.configuration =
file:/var/lib/opens
hift/512f76d34382ecaf
af0
002b8/jbossas-7
/jbossas-7/standal
one/config
uration/logging.prop
ertie
s
module.path =
/va
r/lib/opensh
ift/512f76d34382
ecafaf0
002b8
//jbossas-7/jbossas-7/s
tandalone/
co
nfiguration/modules::/var/lib/openshift/512f76d34382ecafaf0002b8//jbossas-7/jbossas-7/modules
o
rg.apache.coyote
.http11.Http
11Protocol.COMPRESSION
=
on
org.apache.tomcat.ut
i
l.LOW_MEMORY = true

org.jboss.b
oot.log.fil
e = /var/lib/
o
penshift/
512f76d34382ecafaf0002b8/jbossas-7/jbossas-7/standalone/log
/boot.log
o
rg.jboss
.resolver.warning

= true
org.xml.s
ax.drive
r = __redirected.__XML
R
eaderFactory
os.arch = i386
os.name = Linux
os.version = 2.6.32-358.10.1.1.el6.x86_64
path.separat
or
=
:

r
e
be
l
.
l
o
g
=
t
r
ue


re
b
e
l.lo
g
.f
i
le

=

/
v
a
r
/
lib/op
enshift/512f76d34382
e
cafaf0002b8/app-ro
ot/runtime/repo/.jrebe
l/jrebel.lo
g
rebel.remoting_plugin = true
sun.arch.data.model = 32
sun.boot.class.path = /usr/lib/jvm/java-1.
7
.0-
op
e
nj
d
k-
1
.7
.0
.1
9/
j
r
e/
l
ib
/
al
t
-
rt
.
j
a
r
:
/
u
s
r
/
l
ib/jvm/java-1.7
.
0
-
o
p
e
n
jdk-1.7.0
.
1
9
/
jre/l
ib/resources.j
ar:/usr/
l
i
b
/
j
v
m
/
j
a
v
a
-
1
.7.0-openjdk-1.7.0.19/jre/lib/rt.jar:/usr/lib/jvm/java-1
.
7
.
0
-openjdk-1.7.0.19/jre/lib/sunrsasign.jar:/usr/lib/jvm/java-1.7.0-openjdk-1.7.0.19/jre/lib/jsse.jar:/usr/lib/jvm/java-1.7.0-ope
n
jd
k-1.7.0
.19/jre/l
ib/jce.jar:/usr
/li
b/j
vm/java-1.7.0-openjdk-
1.7.0.19/jre/lib/c
harsets.ja
r:/usr/lib/jvm/java-1.7.0-openjdk-1.7.0.19/jre/lib/netx.jar:/
usr/lib/jvm/java-1.7.
0-openjdk-1.7.0.1
9/jre/l
ib/plugin.jar
:/usr/lib/jvm/ja
va-1.7.0-o
penjdk-1.7.0.19/jre/l
ib
/
rhino.jar:/usr/lib/jvm/java-1.7.0-openjdk-1.7.0.19/jre/lib/jfr.jar:/usr/lib/jvm/java-1
.7.0-openjdk-1.7.0.1
9/j
re/classes:/var/li
b/openshift/512f76d3
4382
ecafaf0002b8/ap
p-root/runtime/repo/.j
r
ebel/jrebel.jar
sun.bo
ot.library.path =
/usr/lib/jvm/java-1.7
.0-openjdk-1.7.0.19/j
re/lib/i386
s
un.cpu.endian = little
sun.cpu.isalist =

sun.io.unicode.e
ncoding = Unicode
Little
sun.java
.
command =
/var/lib/openshift/512f76d34382ecafaf0002b8/jbossas-7/jbossas-7/jboss-modules.jar
-mp
/var/lib/openshift/51
2f
76d34382ecafaf0002b8//
jbossas-7/jboss
as-7/standal
one/configurat
ion
/modules::/var/lib/open
shift/512f76d34382ecafa
f00
02b8//jbossas-7/jbossa
s-7/modules -j
axpmodule javax.xml.jaxp-provider o
rg.jboss.as.standalone
-Djboss.hom
e.dir=/var/li
b/op
enshift/512f76d34382ecaf
af0002b8/jbossas-7/
jbossas-7
sun.j
ava.lau
ncher = SUN_STANDARD
sun.jnu.encoding = ANSI_X3.4-1968

sun.management.comp
iler = H
otSpot Tiere
d Compilers
sun.os.pat
c
h.level = unkn
own
user.country = US
user.dir = /var/lib/openshift
/512f76d343
82ecafaf0002b8
user.h
ome = /var/lib
/
openshift/512f76d34382ecafaf0002b8/app-root/runtime/repo/
user.language = en
user.name = 512f76d34
382ecafaf0002b8
use
r.t
imezone = Europe/
Kiev
0
9:41:56,109 D
EBUG [org.jboss.as.c
onfig
] VM Arguments:
-D[Standalone] -Xmx256
m -XX:Max
PermSize=102m -XX:+Agg
ressiveOp
ts -Dorg.apache.
tomcat.util.LOW_MEMORY=true -Dorg.
jboss.resolver
.warning=true -Dja
va.net.pr
eferIPv4S
tack=true -Dfile.encoding=UTF-8 -Djava.net.preferIPv4Stack=true -
Djboss.node.na
me=rs-emetemunoy.rhclou
d
.com -Djgroups.bind_ad
dr=127.12.40.129 -Dorg.a
pach
e.coy
ote.http11.Http11Protocol.COMPRESSION=on
-Dorg.jboss.boot.log.file=/var/lib/open
shift/512f76d34382ecafa
f0002b8/jbos
sas-7/jbossas-7
/standa
lon
e/log/boot.lo
g -Dlogging.configu
ra
t
ion=file:/var/l
ib/openshift/512f76d34382ecafaf0002b8/jbossa
s-7/jbossas-7/standalo
ne/confi
guration/log
ging.properties -Dfile.encoding=UTF8 -Duser
.timezone=Europe/Kiev -
javaagent:/var/lib
/op
enshift/512f7
6d34382ecafaf0002b8/app-root/repo/newrelic/
new
relic.ja
r -javaagent:/var/lib/openshift/512f76d34382ecafaf0002b8/app-root/runt
ime/repo/.jrebel/jrebe
l.jar -Drebel.log=true
-D
rebel.log.file=/var/
lib/openshift/512f76d34
38
2ecafaf0002b
8/app-root/runtime/repo/.jrebel/jrebel.log -Duser.home=/var/
lib/openshift/512f76d343
82ecaf
af0002b8/app-root/runt
ime/repo/ -Drebe
l.remotin
g_plugin=true
09:42
:11,131
ERROR
[org.jboss.msc.service.fail]
MSC00001: Failed
to start service j
boss.deployment-mou
nt-provider: org.jboss
.msc.ser
vice.StartException
in service jboss
.deployment-mount-provi
der: JBAS015843: Failed
to create temp file provid
er
at org.jbo
ss.as.server.deployment
.DeploymentMoun
tProvider$Factory$ServerDep
loymentRepositoryImpl.start(De
ploymentMountProvider.
java:111) [j
bo
ss-as-server-7
.1.1.Final.jar:7.1.1.
Final]
at org.jboss.ms
c.se
rvice.Service
ControllerImpl$Star
tTask.startServ
ice(ServiceControllerImpl.java:1811)
[jboss-msc-1.0.2.GA.ja
r:1.0.2.GA]
at org.jb
oss.ms
c.servi
ce.ServiceControllerImpl$StartTask.run(ServiceControllerImpl.java:1746)
[jboss-msc-1.0.2.GA.ja
r:1.0.2.GA]
at jav
a.util.concurrent.Threa
dPoolExecutor.runWorker
(ThreadPoolExecutor.java
:1145) [rt.jar:1.7.0_
19]
at java
.util.concurr
ent.ThreadPoo
lExecutor$Worker.run(ThreadPoolExecutor.java:615)
[rt.jar:1.7.0_19]
at java.lang.Thread.run
(Thread.java:722) [rt
.jar:1.7.0_
19]

Expected results:
18:35:20,208 INFO  [jacorb.orb] prepare ORB for shutdown...
18:35:20,208 INFO  [jacorb.orb] ORB going down...
18:35:20,708 INFO  [jacorb.orb] ORB shutdown complete
18:35:20,803 INFO  [jacorb.orb] ORB run, exit
18:35:20,806 INFO  [org.hornetq.ra.HornetQResourceAdapter] HornetQ resource adapter stopped
18:35:20,891 INFO  [jacorb.orb.iiop] Listener exited
18:35:21,385 INFO  [com.arjuna.ats.jbossatx] ARJUNA032018: Destroying TransactionManagerService
18:35:21,525 INFO  [com.arjuna.ats.jbossatx] ARJUNA032014: Stopping transaction recovery manager
18:35:22,413 INFO  [org.hornetq.core.server.impl.HornetQServerImpl] HornetQ Server version 2.2.13.Final (HQ_2_2_13_FINAL_AS7, 122) [18071150-81bb-11e2-84bd-1231380a2e48] stopped
18:35:22,703 INFO  [org.jboss.as] JBAS015950: JBoss AS 7.1.1.Final "Brontes" stopped in 6457ms


Additional info:

Comment 1 Justin Harris 2013-05-30 19:06:09 UTC
I have not been able to reproduce this issue in devenv or production.  From the logs, this appears to be a result of a node failure.

Comment 2 Ihor 2013-05-30 19:30:40 UTC
"to be a result of a node failure."
no, I think this is not the node failure, because I destroy and recreate my "rs" application 03 times, and this problem is still.
I use ubuntu 13.04 32bit.
also rhc ssh work good, command "cat server.log" also work good

Comment 3 Bill DeCoste 2013-05-30 20:15:09 UTC
The problem with the ugly output is the network latency. 'rhc tail' is pulling the logs over ssh. Best way to get around this is to ssh into the gear and tail the logs directly.

Comment 4 Ihor 2013-05-31 06:27:22 UTC
I live in Ukraine, Europe, and when I do Git push to OpenShift 98% I have timeout message(in IDE Eclipse) but push is done.

http://www.speedtest.net/result/2742776229.png Ukraine

http://www.speedtest.net/result/2742778709.png Europe

http://www.speedtest.net/result/2742783030.png USA

ihor@ihor-M50Vc:~$ rhc app restart -a rs -d
DEBUG: Authenticating with RHC::Auth::Basic
DEBUG: Connecting to https://openshift.redhat.com/broker/rest/api
DEBUG: Getting all domains
DEBUG: Request GET https://openshift.redhat.com/broker/rest/api
DEBUG:    code 200  963 ms
Password: ******
DEBUG: Request GET https://openshift.redhat.com/broker/rest/domains
DEBUG:    code 200 1416 ms
DEBUG: Getting all domains
DEBUG: Request GET https://openshift.redhat.com/broker/rest/domains/emetemunoy/applications/rs
DEBUG:    code 200 1195 ms
DEBUG: Restarting application rs
DEBUG: Request POST https://openshift.redhat.com/broker/rest/domains/emetemunoy/applications/rs/events
DEBUG:    code 500 55281 ms
Unable to complete the requested operation due to: Node execution failure
(invalid exit code from node).  If the problem persists please contact Red Hat
support..
Reference ID: 980825f99c18e64be66703209389d94f
ihor@ihor-M50Vc:~$ 

ihor@ihor-M50Vc:~$ ping openshift.redhat.com
PING ex-elb1-prod-1847871222.us-east-1.elb.amazonaws.com (54.225.207.48) 56(84) bytes of data.
^C
--- ex-elb1-prod-1847871222.us-east-1.elb.amazonaws.com ping statistics ---
75 packets transmitted, 0 received, 100% packet loss, time 73999ms

ihor@ihor-M50Vc:~$ ping openshift.redhat.com
PING ex-elb1-prod-1847871222.us-east-1.elb.amazonaws.com (204.236.234.70) 56(84) bytes of data.
^C
--- ex-elb1-prod-1847871222.us-east-1.elb.amazonaws.com ping statistics ---
20 packets transmitted, 0 received, 100% packet loss, time 18999ms

ihor@ihor-M50Vc:~$ ping redhat.com
PING redhat.com (209.132.183.181) 56(84) bytes of data.
64 bytes from 209.132.183.181: icmp_req=1 ttl=232 time=258 ms
64 bytes from 209.132.183.181: icmp_req=2 ttl=232 time=259 ms
64 bytes from 209.132.183.181: icmp_req=3 ttl=232 time=260 ms
64 bytes from 209.132.183.181: icmp_req=4 ttl=232 time=263 ms
64 bytes from 209.132.183.181: icmp_req=5 ttl=232 time=262 ms
^C64 bytes from 209.132.183.181: icmp_req=6 ttl=232 time=259 ms

--- redhat.com ping statistics ---
6 packets transmitted, 6 received, 0% packet loss, time 76356ms
rtt min/avg/max/mdev = 258.963/260.767/263.562/1.858 ms
ihor@ihor-M50Vc:~$ ping mobile.de
PING mobile.de (91.211.75.176) 56(84) bytes of data.
64 bytes from 91.211.75.176: icmp_req=1 ttl=243 time=87.8 ms
64 bytes from 91.211.75.176: icmp_req=2 ttl=243 time=85.8 ms
64 bytes from 91.211.75.176: icmp_req=3 ttl=243 time=90.4 ms
64 bytes from 91.211.75.176: icmp_req=4 ttl=243 time=90.3 ms
64 bytes from 91.211.75.176: icmp_req=5 ttl=243 time=90.3 ms
64 bytes from 91.211.75.176: icmp_req=6 ttl=243 time=90.6 ms
64 bytes from 91.211.75.176: icmp_req=7 ttl=243 time=90.6 ms
^C64 bytes from 91.211.75.176: icmp_req=8 ttl=243 time=87.7 ms

--- mobile.de ping statistics ---
8 packets transmitted, 8 received, 0% packet loss, time 36102ms
rtt min/avg/max/mdev = 85.827/89.239/90.660/1.755 ms

Comment 5 Ihor 2013-05-31 13:02:28 UTC
you can see) this bug is still from 2013-02-21
https://bugzilla.redhat.com/show_bug.cgi?id=913459

Comment 6 Balazs Varga 2014-07-23 12:30:44 UTC
The log messages problem caused by network latency / lack of bandwith.

If you still have issue with restarting your application please open a new bug with more details.