Bug 1319257

Summary:	[RH Ceph 2.0] rados test_python assert during logrotate AssertionError: 140352653072300 != 'arg'
Product:	Red Hat Ceph Storage	Reporter:	Vasu Kulkarni <vakulkar>
Component:	RADOS	Assignee:	Samuel Just <sjust>
Status:	CLOSED NOTABUG	QA Contact:	ceph-qe-bugs <ceph-qe-bugs>
Severity:	medium	Docs Contact:
Priority:	unspecified
Version:	2.0	CC:	ceph-eng-bugs, dzafman, hnallurv, jdurgin, kchai, nlevine, vakulkar
Target Milestone:	rc
Target Release:	2.0
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:		Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2016-04-06 17:58:16 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:

Description Vasu Kulkarni 2016-03-18 16:16:39 UTC

Description of problem:

:AssertionError: 140352653072300 != 'arg'

2016-03-18T03:30:30.861 INFO:tasks.workunit.client.0.clara008.stderr:test_rados.TestRados.test_list_pools ... ok
2016-03-18T03:30:30.945 INFO:tasks.workunit.client.0.clara008.stderr:test_rados.TestRados.test_monitor_log ... Traceback (most recent call last):
2016-03-18T03:30:30.946 INFO:tasks.workunit.client.0.clara008.stderr:  File "_ctypes/callbacks.c", line 314, in 'calling callback function'
2016-03-18T03:30:30.947 INFO:tasks.workunit.client.0.clara008.stderr:  File "/usr/lib/python2.7/site-packages/rados.py", line 2442, in monitor_log_callback
2016-03-18T03:30:30.949 INFO:tasks.workunit.client.0.clara008.stderr:    self.callback(arg, line, who, sec, nsec, seq, level, msg)
2016-03-18T03:30:30.950 INFO:tasks.workunit.client.0.clara008.stderr:  File "/home/ubuntu/cephtest/mnt.0/client.0/tmp/test_rados.py", line 258, in cb
2016-03-18T03:30:30.951 INFO:tasks.workunit.client.0.clara008.stderr:    eq(arg, "arg")
2016-03-18T03:30:30.952 INFO:tasks.workunit.client.0.clara008.stderr:  File "/usr/lib/python2.7/site-packages/nose/tools/trivial.py", line 29, in eq_
2016-03-18T03:30:30.953 INFO:tasks.workunit.client.0.clara008.stderr:    raise AssertionError(msg or "%r != %r" % (a, b))
2016-03-18T03:30:30.954 INFO:tasks.workunit.client.0.clara008.stderr:AssertionError: 140352653072300 != 'arg'

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

How reproducible:
Unknown


Steps to Reproduce:
Assertion is seen during test_rados.py during smoke run

Actual results:

2016-03-18T03:30:00.531 INFO:tasks.workunit.client.0.clara008.stderr:test_rados.TestObject.test_read ... ok
2016-03-18T03:30:03.590 INFO:tasks.workunit.client.0.clara008.stderr:test_rados.TestObject.test_seek ... ok
2016-03-18T03:30:06.602 INFO:tasks.workunit.client.0.clara008.stderr:test_rados.TestObject.test_write ... ok
2016-03-18T03:30:07.603 INFO:tasks.workunit.client.0.clara008.stderr:test_rados.TestRados.test_blacklist_add ... ok
2016-03-18T03:30:09.656 INFO:tasks.workunit.client.0.clara008.stderr:test_rados.TestRados.test_create ... ok
2016-03-18T03:30:11.661 INFO:tasks.workunit.client.0.clara008.stderr:test_rados.TestRados.test_create_auid ... ok
2016-03-18T03:30:13.714 INFO:tasks.workunit.client.0.clara008.stderr:test_rados.TestRados.test_create_utf8 ... ok
2016-03-18T03:30:15.717 INFO:tasks.workunit.client.0.clara008.stderr:test_rados.TestRados.test_eexist ... ok
2016-03-18T03:30:15.804 INFO:tasks.workunit.client.0.clara008.stderr:test_rados.TestRados.test_get_cluster_stats ... ok
2016-03-18T03:30:15.891 INFO:tasks.workunit.client.0.clara008.stderr:test_rados.TestRados.test_get_fsid ... ok
2016-03-18T03:30:22.778 INFO:tasks.workunit.client.0.clara008.stderr:test_rados.TestRados.test_get_pool_base_tier ... ok
2016-03-18T03:30:30.382 INFO:teuthology.orchestra.run.clara008:Running: 'sudo logrotate /etc/logrotate.d/ceph-test.conf'
2016-03-18T03:30:30.390 INFO:teuthology.orchestra.run.clara009:Running: 'sudo logrotate /etc/logrotate.d/ceph-test.conf'
2016-03-18T03:30:30.398 INFO:teuthology.orchestra.run.clara014:Running: 'sudo logrotate /etc/logrotate.d/ceph-test.conf'
2016-03-18T03:30:30.861 INFO:tasks.workunit.client.0.clara008.stderr:test_rados.TestRados.test_list_pools ... ok
2016-03-18T03:30:30.945 INFO:tasks.workunit.client.0.clara008.stderr:test_rados.TestRados.test_monitor_log ... Traceback (most recent call last):
2016-03-18T03:30:30.946 INFO:tasks.workunit.client.0.clara008.stderr:  File "_ctypes/callbacks.c", line 314, in 'calling callback function'
2016-03-18T03:30:30.947 INFO:tasks.workunit.client.0.clara008.stderr:  File "/usr/lib/python2.7/site-packages/rados.py", line 2442, in monitor_log_callback
2016-03-18T03:30:30.949 INFO:tasks.workunit.client.0.clara008.stderr:    self.callback(arg, line, who, sec, nsec, seq, level, msg)
2016-03-18T03:30:30.950 INFO:tasks.workunit.client.0.clara008.stderr:  File "/home/ubuntu/cephtest/mnt.0/client.0/tmp/test_rados.py", line 258, in cb
2016-03-18T03:30:30.951 INFO:tasks.workunit.client.0.clara008.stderr:    eq(arg, "arg")
2016-03-18T03:30:30.952 INFO:tasks.workunit.client.0.clara008.stderr:  File "/usr/lib/python2.7/site-packages/nose/tools/trivial.py", line 29, in eq_
2016-03-18T03:30:30.953 INFO:tasks.workunit.client.0.clara008.stderr:    raise AssertionError(msg or "%r != %r" % (a, b))
2016-03-18T03:30:30.954 INFO:tasks.workunit.client.0.clara008.stderr:AssertionError: 140352653072300 != 'arg'
2016-03-18T03:30:31.860 INFO:tasks.workunit.client.0.clara008.stderr:Traceback (most recent call last):
2016-03-18T03:30:31.861 INFO:tasks.workunit.client.0.clara008.stderr:  File "_ctypes/callbacks.c", line 314, in 'calling callback function'
2016-03-18T03:30:31.862 INFO:tasks.workunit.client.0.clara008.stderr:  File "/usr/lib/python2.7/site-packages/rados.py", line 2442, in monitor_log_callback
2016-03-18T03:30:31.863 INFO:tasks.workunit.client.0.clara008.stderr:    self.callback(arg, line, who, sec, nsec, seq, level, msg)
2016-03-18T03:30:31.864 INFO:tasks.workunit.client.0.clara008.stderr:  File "/home/ubuntu/cephtest/mnt.0/client.0/tmp/test_rados.py", line 258, in cb
2016-03-18T03:30:31.866 INFO:tasks.workunit.client.0.clara008.stderr:    eq(arg, "arg")
2016-03-18T03:30:31.867 INFO:tasks.workunit.client.0.clara008.stderr:  File "/usr/lib/python2.7/site-packages/nose/tools/trivial.py", line 29, in eq_
2016-03-18T03:30:31.868 INFO:tasks.workunit.client.0.clara008.stderr:    raise AssertionError(msg or "%r != %r" % (a, b))
2016-03-18T03:30:31.869 INFO:tasks.workunit.client.0.clara008.stderr:AssertionError: 140352653072300 != 'arg'

Expected results:


Additional info:

http://magna002.ceph.redhat.com/vasu-2016-03-17_19:50:58-smoke-master---basic-clara/215656/teuthology.log

Comment 2 Samuel Just 2016-03-18 20:44:21 UTC

*** Bug 1319258 has been marked as a duplicate of this bug. ***

Comment 3 Josh Durgin 2016-03-23 00:44:25 UTC

Vasu, could you try against the jewel branch? This doesn't occur in the upstream tests, so I'm curious whether this is an artifact of the environment (e.g. distro) or just an issue fixed since 10.0.4.

Comment 4 Vasu Kulkarni 2016-03-28 22:28:05 UTC

Josh,

I can try this only on jewel after next rebase of 10.1.0, For now I have recreated this on second build which is still 10.0.4 but a newer one, I am just running one Class now where I have seen the assert, If you want you can use the below testnode which I have left in same state.


[ubuntu@magna091 ~]$ ceph -v
ceph version 10.0.4-2.el7cp (61adb020219fbad4508050b5f0a792246ba74dae)


ssh ubuntu@magna091 and from home dir you can run
nosetests -v simple_test_rados.py

AssertionError: 139652378310452 != 'arg'
Traceback (most recent call last):
  File "_ctypes/callbacks.c", line 314, in 'calling callback function'
  File "/usr/lib/python2.7/site-packages/rados.py", line 2442, in monitor_log_callback
    self.callback(arg, line, who, sec, nsec, seq, level, msg)
  File "/home/ubuntu/simple_test_rados.py", line 144, in cb

Comment 5 Vasu Kulkarni 2016-04-06 17:58:16 UTC

This worked on newer rebase of 10.1.0, Closing as not a bug.