Bug 696943 - logs got by virtio are different from the originals on guest
Summary: logs got by virtio are different from the originals on guest
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: lorax
Version: 15
Hardware: x86_64
OS: Linux
unspecified
medium
Target Milestone: ---
Assignee: Ales Kozumplik
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard: AcceptedNTH
Depends On:
Blocks: F15-accepted, F15FinalFreezeExcept
TreeView+ depends on / blocked
 
Reported: 2011-04-15 11:17 UTC by Hongqing Yang
Modified: 2014-09-30 23:40 UTC (History)
8 users (show)

Fixed In Version: lorax-0.4.4-1.fc15
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2011-05-05 05:00:36 UTC
Type: ---
Embargoed:


Attachments (Terms of Use)
anaconda.log got by virtio (32.77 KB, text/plain)
2011-04-15 11:21 UTC, Hongqing Yang
no flags Details
ifcfg.log got by virtio (1.35 KB, text/plain)
2011-04-15 11:21 UTC, Hongqing Yang
no flags Details
program.log got by virtio (20.96 KB, text/plain)
2011-04-15 11:22 UTC, Hongqing Yang
no flags Details
storage.log got by virtio (73.24 KB, text/plain)
2011-04-15 11:22 UTC, Hongqing Yang
no flags Details
syslog got by virtio (51.98 KB, text/plain)
2011-04-15 11:23 UTC, Hongqing Yang
no flags Details
X.log got by virtio (25.14 KB, text/plain)
2011-04-15 11:24 UTC, Hongqing Yang
no flags Details
original anaconda.log on guest (34.85 KB, text/plain)
2011-04-15 11:33 UTC, Hongqing Yang
no flags Details
original program.log on guest (23.78 KB, text/plain)
2011-04-15 11:34 UTC, Hongqing Yang
no flags Details
original storage.log on guest (117.46 KB, text/plain)
2011-04-15 11:35 UTC, Hongqing Yang
no flags Details
original syslog on guest (51.82 KB, text/plain)
2011-04-15 11:35 UTC, Hongqing Yang
no flags Details
original xlog on guest (24.62 KB, text/plain)
2011-04-15 11:36 UTC, Hongqing Yang
no flags Details
original ifcfg.log on guest (1.29 KB, text/plain)
2011-04-15 11:36 UTC, Hongqing Yang
no flags Details
debug_all log (168.81 KB, text/plain)
2011-04-18 02:57 UTC, Hongqing Yang
no flags Details
debug unknown source log (381 bytes, text/plain)
2011-04-18 02:58 UTC, Hongqing Yang
no flags Details
debug unknown source log after turn off rate limit (253 bytes, text/plain)
2011-04-18 11:26 UTC, Hongqing Yang
no flags Details
debug all log after turn off rate limit (464 bytes, text/plain)
2011-04-18 11:27 UTC, Hongqing Yang
no flags Details
rsyslogd.conf after turn off rate limit (2.85 KB, text/plain)
2011-04-18 11:29 UTC, Hongqing Yang
no flags Details
anaconda logs, debug logs, ks.cfg, create_command.sh (86.97 KB, application/zip)
2011-04-27 03:05 UTC, Hongqing Yang
no flags Details

Description Hongqing Yang 2011-04-15 11:17:04 UTC
Description of problem:

The logs got by virtio are different from the originals on the guest.

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


How reproducible:
100%

Steps to Reproduce:
1. start rsyslog service
2. run analog
3. create a guest
4. edit guest xml to add channel
5. restart guest
  
Actual results:


Expected results:


Additional info:

Comment 1 Hongqing Yang 2011-04-15 11:21:08 UTC
Created attachment 492336 [details]
anaconda.log got by virtio

Comment 2 Hongqing Yang 2011-04-15 11:21:44 UTC
Created attachment 492337 [details]
ifcfg.log got by virtio

Comment 3 Hongqing Yang 2011-04-15 11:22:13 UTC
Created attachment 492338 [details]
program.log got by virtio

Comment 4 Hongqing Yang 2011-04-15 11:22:52 UTC
Created attachment 492339 [details]
storage.log got by virtio

Comment 5 Hongqing Yang 2011-04-15 11:23:35 UTC
Created attachment 492340 [details]
syslog got by virtio

Comment 6 Hongqing Yang 2011-04-15 11:24:45 UTC
Created attachment 492341 [details]
X.log got by virtio

Comment 7 Hongqing Yang 2011-04-15 11:33:33 UTC
Created attachment 492342 [details]
original anaconda.log on guest

Comment 8 Hongqing Yang 2011-04-15 11:34:13 UTC
Created attachment 492344 [details]
original program.log on guest

Comment 9 Hongqing Yang 2011-04-15 11:35:12 UTC
Created attachment 492347 [details]
original storage.log on guest

Comment 10 Hongqing Yang 2011-04-15 11:35:43 UTC
Created attachment 492348 [details]
original syslog on guest

Comment 11 Hongqing Yang 2011-04-15 11:36:18 UTC
Created attachment 492349 [details]
original  xlog on guest

Comment 12 Hongqing Yang 2011-04-15 11:36:52 UTC
Created attachment 492350 [details]
original ifcfg.log on guest

Comment 13 Hongqing Yang 2011-04-15 11:40:54 UTC
some difference in anaconda.log 

there is record line in the original anaconda.log

moving (1) to step storagedone

but it cannot be found in the anaconda.log got by virtio.

Comment 14 Ales Kozumplik 2011-04-15 13:24:58 UTC
Hi,

Please attach debug_all.log and debug_unknown.log from the analog output directory.

Comment 15 Ales Kozumplik 2011-04-15 13:26:17 UTC
Btw,

Why is the version 14? Isn't this supposed to be 15 or rawhide?

Comment 16 Hongqing Yang 2011-04-18 02:57:26 UTC
Created attachment 492791 [details]
debug_all log

Comment 17 Hongqing Yang 2011-04-18 02:58:27 UTC
Created attachment 492792 [details]
debug unknown source log

Comment 18 Hongqing Yang 2011-04-18 02:59:16 UTC
It should be F15, the host is F14 x86_64

Comment 19 Ales Kozumplik 2011-04-18 07:55:22 UTC
I think this is caused by this rsyslogd feature: http://www.rsyslog.com/how-to-use-rate-limiting-in-rsyslog/ which is turned on by default.

Patch 99f5ecf219c4668bd2b8c41499b504683b90a2ca on master is fixing this, please retest with analog from anaconda-16.6-1 once that becomes available or for a quick fix try adding 

$SystemLogRateLimitInterval 0

after 

$ModLoad imuxsock

in the generated rsyslogd file (you'll need to do that before rsyslogd starts though).

Comment 20 Hongqing Yang 2011-04-18 11:24:54 UTC
I have checked out the latest anaconda, I saw you have add $SystemLogRateLimitInterval 0 in it. but when I run 
eval `./analog -p 6080 -s -o .rsyslogd.conf /tmp/autoqa/log/`

it gives error in the debug logs, please find it in the attachments.

I have tried to add $SystemLogRateLimitInterval 0  into /etc/rsyslog.conf,
it also does not work.

Comment 21 Hongqing Yang 2011-04-18 11:26:37 UTC
Created attachment 492860 [details]
debug unknown source log after turn off rate limit

Comment 22 Hongqing Yang 2011-04-18 11:27:09 UTC
Created attachment 492861 [details]
debug all log after turn off rate limit

Comment 23 Hongqing Yang 2011-04-18 11:29:09 UTC
Created attachment 492862 [details]
rsyslogd.conf after turn off rate limit

Comment 24 Ales Kozumplik 2011-04-18 13:09:55 UTC
Hm,

can you also try like this:

$ModLoad imtcp.so
$ModLoad imuxsock.so
$SystemLogRateLimitInterval 0
$OmitLocalLogging on
$InputTCPServerRun 6080

that is, swapping $OmitLocalLogging and $SystemLogRateLimitInterval?

Thanks.

Comment 25 Hongqing Yang 2011-04-19 03:02:32 UTC
It seems the situation is the same. even I add it to /etc/rsyslog.conf, restart the rsyslog service,  the same error found in /var/log/messages. Do you think it is a problem of rsyslog? Thanks.

Comment 26 Hongqing Yang 2011-04-26 06:19:29 UTC
Hi, Ales

I have contacted with Rainer, I was told the rsyslog version 4.6.3 does not support the new type of rate limiting.

Comment 27 Ales Kozumplik 2011-04-26 08:32:11 UTC
Can you please retest with an f15/rawhide which should already have rsyslogd >= 5.7 ?

Thanks.

Comment 28 Hongqing Yang 2011-04-26 11:16:41 UTC
Hi, Ales,

I have tested f15 with rsyslog 5.7.9,  the error messages in attachment  https://bugzilla.redhat.com/attachment.cgi?id=492861  disappear, but the logs are still different.

Comment 29 Ales Kozumplik 2011-04-26 11:25:40 UTC
(In reply to comment #28)
> Hi, Ales,
> 
> I have tested f15 with rsyslog 5.7.9,  the error messages in attachment 
> https://bugzilla.redhat.com/attachment.cgi?id=492861  disappear, but the logs
> are still different.

Please re-attach all the logs from the 5.7 attempt, can be as a single, reasonably structured zip file.

Comment 30 Hongqing Yang 2011-04-27 03:05:07 UTC
Created attachment 495104 [details]
anaconda logs, debug logs, ks.cfg, create_command.sh

Comment 31 Ales Kozumplik 2011-04-27 06:43:43 UTC
(In reply to comment #30)
> Created attachment 495104 [details]
> anaconda logs, debug logs, ks.cfg, create_command.sh

That's interesting. Assuming you are using the latest 'analog' to generate the rsyslogd config which disables rate limiting via

$SystemLogRateLimitInterval 0

it looks like an rsyslogd bug to still have messages dropped as indicated in debug_unknown_source.log:

<46>2011-04-26T02:50:50.006142+00:00 localhost rsyslogd-2177: imuxsock begins to drop messages from pid 364 due to rate-limiting
<46>2011-04-26T02:50:51.552511+00:00 localhost rsyslogd-2177: imuxsock lost 458 messages from pid 364 due to rate-limiting
<46>2011-04-26T02:56:26.284391+00:00 localhost rsyslogd-2177: imuxsock begins to drop messages from pid 364 due to rate-limiting

I will talk to the rsyslogd maintainer about this later today.

Comment 32 Ales Kozumplik 2011-04-27 11:57:10 UTC
The rsyslogd maintainer explained that this is caused by the guest side dropping messages. Rawhide fix in the rsyslogd config will follow. 

Hongqing, I don't think we will be able to get this to F15, it is hard to imagine the issue as a blocker.

Comment 33 James Laska 2011-04-27 17:14:32 UTC
(In reply to comment #32)
> Hongqing, I don't think we will be able to get this to F15, it is hard to
> imagine the issue as a blocker.

Depending on the scope of the fix, since this is really helpful for our test automation, I think this would fit as a nice-to-have for F15.

Comment 34 Ales Kozumplik 2011-04-28 07:32:36 UTC
In master lorax this is fixed by:
http://git.fedorahosted.org/git/?p=lorax.git;a=commitdiff;h=7a77fdc7abefe71aa7c427890ff716e87a95ebc2

Will cherry-pick to f15 if this (low risk) patch becomes an accepted NTH.

Comment 35 Adam Williamson 2011-04-29 18:32:55 UTC
Discussed at 2011-04-29 NTH review meeting, accepted NTH per comments #33 and #34.



-- 
Fedora Bugzappers volunteer triage team
https://fedoraproject.org/wiki/BugZappers

Comment 36 Ales Kozumplik 2011-05-02 06:55:50 UTC
Fixed by 78709fe0291b9a9568fc193a350cd3716a6f05a1 on the f15-branch.

Comment 37 James Laska 2011-05-02 19:21:57 UTC
(In reply to comment #36)
> Fixed by 78709fe0291b9a9568fc193a350cd3716a6f05a1 on the f15-branch.

We still need a build submitted for this so it can land in F15.

Comment 38 James Laska 2011-05-02 19:59:10 UTC
(In reply to comment #37)
> (In reply to comment #36)
> > Fixed by 78709fe0291b9a9568fc193a350cd3716a6f05a1 on the f15-branch.
> 
> We still need a build submitted for this so it can land in F15.

Many thanks to mcepl who submitted a bodhi update for this issue

https://admin.fedoraproject.org/updates/lorax-0.4.4-1.fc15

Comment 39 Fedora Update System 2011-05-02 20:02:02 UTC
lorax-0.4.4-1.fc15 has been submitted as an update for Fedora 15.
https://admin.fedoraproject.org/updates/lorax-0.4.4-1.fc15

Comment 40 Fedora Update System 2011-05-03 04:28:34 UTC
Package lorax-0.4.4-1.fc15:
* should fix your issue,
* was pushed to the Fedora 15 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing lorax-0.4.4-1.fc15'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/lorax-0.4.4-1.fc15
then log in and leave karma (feedback).

Comment 41 Fedora Update System 2011-05-05 05:00:29 UTC
lorax-0.4.4-1.fc15 has been pushed to the Fedora 15 stable repository.  If problems still persist, please make note of it in this bug report.

Comment 42 Hongqing Yang 2011-05-09 05:54:55 UTC
it works well with rsyslog 5.7.9-2.fc15.x86_64 and lorax 0.4.5.1.fc15.x86_64


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