Actions
Bug #23327
openqa: pjd test sees wrong ctime after unlink
Status:
New
Priority:
High
Assignee:
-
Category:
Correctness/Safety
Target version:
-
% Done:
0%
Source:
Development
Tags:
Backport:
mimic,luminous
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Component(FS):
Client, MDS
Labels (FS):
qa
Pull request ID:
Crash signature (v1):
Crash signature (v2):
Description
Important bits:
2018-03-09T21:03:52.361 INFO:tasks.workunit.client.0.smithi093.stderr:+ expect 0 link fstest_8fe01137292cb05d76c79755efa01e8e fstest_2986a053de976940aec2ea0ba5883209 2018-03-09T21:03:52.362 INFO:tasks.workunit.client.0.smithi093.stderr:+ e=0 2018-03-09T21:03:52.362 INFO:tasks.workunit.client.0.smithi093.stderr:+ shift 2018-03-09T21:03:52.362 INFO:tasks.workunit.client.0.smithi093.stderr:++ /home/ubuntu/cephtest/mnt.0/client.0/tmp/tmp/../pjd-fstest-20090130-RC/tests/unlink/../../fstest link fstest_8fe01137292cb05d76c79755efa01e8e fstest_2986a053de976940aec2ea0ba5883209 2018-03-09T21:03:52.362 INFO:tasks.workunit.client.0.smithi093.stderr:++ tail -1 2018-03-09T21:03:52.362 INFO:tasks.workunit.client.0.smithi093.stderr:+ r=0 2018-03-09T21:03:52.362 INFO:tasks.workunit.client.0.smithi093.stderr:+ echo 0 2018-03-09T21:03:52.362 INFO:tasks.workunit.client.0.smithi093.stderr:+ egrep '^0$' 2018-03-09T21:03:52.362 INFO:tasks.workunit.client.0.smithi093.stderr:+ '[' 0 -eq 0 ']' 2018-03-09T21:03:52.362 INFO:tasks.workunit.client.0.smithi093.stderr:+ echo 'ok 15' 2018-03-09T21:03:52.362 INFO:tasks.workunit.client.0.smithi093.stderr:++ expr 15 + 1 2018-03-09T21:03:52.363 INFO:tasks.workunit.client.0.smithi093.stderr:+ ntest=16 2018-03-09T21:03:52.363 INFO:tasks.workunit.client.0.smithi093.stderr:++ /home/ubuntu/cephtest/mnt.0/client.0/tmp/tmp/../pjd-fstest-20090130-RC/tests/unlink/../../fstest stat fstest_8fe01137292cb05d76c79755efa01e8e ctime 2018-03-09T21:03:52.363 INFO:tasks.workunit.client.0.smithi093.stderr:+ ctime1=1520629431 2018-03-09T21:03:52.363 INFO:tasks.workunit.client.0.smithi093.stderr:+ sleep 1 2018-03-09T21:03:52.375 INFO:tasks.workunit.client.0.smithi093.stderr:+ expect 0 unlink fstest_2986a053de976940aec2ea0ba5883209 2018-03-09T21:03:52.376 INFO:tasks.workunit.client.0.smithi093.stderr:+ e=0 2018-03-09T21:03:52.376 INFO:tasks.workunit.client.0.smithi093.stderr:+ shift 2018-03-09T21:03:52.376 INFO:tasks.workunit.client.0.smithi093.stderr:++ /home/ubuntu/cephtest/mnt.0/client.0/tmp/tmp/../pjd-fstest-20090130-RC/tests/unlink/../../fstest unlink fstest_2986a053de976940aec2ea0ba5883209 2018-03-09T21:03:52.376 INFO:tasks.workunit.client.0.smithi093.stderr:++ tail -1 2018-03-09T21:03:52.376 INFO:tasks.workunit.client.0.smithi093.stderr:+ r=0 2018-03-09T21:03:52.376 INFO:tasks.workunit.client.0.smithi093.stderr:+ echo 0 2018-03-09T21:03:52.376 INFO:tasks.workunit.client.0.smithi093.stderr:+ egrep '^0$' 2018-03-09T21:03:52.376 INFO:tasks.workunit.client.0.smithi093.stderr:+ '[' 0 -eq 0 ']' 2018-03-09T21:03:52.376 INFO:tasks.workunit.client.0.smithi093.stderr:+ echo 'ok 16' 2018-03-09T21:03:52.377 INFO:tasks.workunit.client.0.smithi093.stderr:++ expr 16 + 1 2018-03-09T21:03:52.377 INFO:tasks.workunit.client.0.smithi093.stderr:+ ntest=17 2018-03-09T21:03:52.377 INFO:tasks.workunit.client.0.smithi093.stderr:++ /home/ubuntu/cephtest/mnt.0/client.0/tmp/tmp/../pjd-fstest-20090130-RC/tests/unlink/../../fstest stat fstest_8fe01137292cb05d76c79755efa01e8e ctime 2018-03-09T21:03:52.377 INFO:tasks.workunit.client.0.smithi093.stderr:+ ctime2=1520629431 2018-03-09T21:03:52.377 INFO:tasks.workunit.client.0.smithi093.stderr:+ test_check 1520629431 -lt 1520629431 2018-03-09T21:03:52.377 INFO:tasks.workunit.client.0.smithi093.stderr:+ '[' 1520629431 -lt 1520629431 ']' 2018-03-09T21:03:52.377 INFO:tasks.workunit.client.0.smithi093.stderr:+ echo 'not ok 17'
In my own tests, the ctime is always correct but the pjd test is rounding. I think that's the cause. Looking at the logs didn't indicate anything wrong with the ctime updates. My own testing shows the ctime updating correctly after unlink.
Updated by Patrick Donnelly about 6 years ago
It may be that the sleep was cut short but I'm not sure we can trust the timestamps from teuthology because the output is buffered.
We have the same problem in another test:
/ceph/teuthology-archive/pdonnell-2018-03-11_22:35:42-fs-wip-pdonnell-testing-20180311.180352-testing-basic-smithi/2279245/teuthology.log
2018-03-13T03:36:03.527 INFO:tasks.workunit.client.0.smithi023.stderr:++ /home/ubuntu/cephtest/mnt.0/client.0/tmp/tmp/../pjd-fstest-20090130-RC/tests/chmod/../../fstest stat fstest_e4841eea1a6b4fc7067ae31d4f7dbf1a ctime 2018-03-13T03:36:03.527 INFO:tasks.workunit.client.0.smithi023.stderr:+ ctime1=1520912163 2018-03-13T03:36:03.527 INFO:tasks.workunit.client.0.smithi023.stderr:+ sleep 1 2018-03-13T03:36:03.530 INFO:teuthology.orchestra.run.smithi040:Running: 'sudo logrotate /etc/logrotate.d/ceph-test.conf' 2018-03-13T03:36:03.815 INFO:tasks.workunit.client.0.smithi023.stderr:+ expect 0 chmod fstest_e4841eea1a6b4fc7067ae31d4f7dbf1a 0111 2018-03-13T03:36:03.815 INFO:tasks.workunit.client.0.smithi023.stderr:+ e=0 2018-03-13T03:36:03.815 INFO:tasks.workunit.client.0.smithi023.stderr:+ shift 2018-03-13T03:36:03.817 INFO:tasks.workunit.client.0.smithi023.stderr:++ /home/ubuntu/cephtest/mnt.0/client.0/tmp/tmp/../pjd-fstest-20090130-RC/tests/chmod/../../fstest chmod fstest_e4841eea1a6b4fc7067ae31d4f7dbf1a 0111 2018-03-13T03:36:03.866 INFO:tasks.workunit.client.0.smithi023.stderr:++ tail -1 2018-03-13T03:36:03.867 INFO:tasks.workunit.client.0.smithi023.stderr:+ r=0 2018-03-13T03:36:03.867 INFO:tasks.workunit.client.0.smithi023.stderr:+ echo 0 2018-03-13T03:36:03.867 INFO:tasks.workunit.client.0.smithi023.stderr:+ egrep '^0$' 2018-03-13T03:36:03.867 INFO:tasks.workunit.client.0.smithi023.stderr:+ '[' 0 -eq 0 ']' 2018-03-13T03:36:03.867 INFO:tasks.workunit.client.0.smithi023.stderr:+ echo 'ok 26' 2018-03-13T03:36:03.867 INFO:tasks.workunit.client.0.smithi023.stderr:++ expr 26 + 1 2018-03-13T03:36:03.867 INFO:tasks.workunit.client.0.smithi023.stderr:+ ntest=27 2018-03-13T03:36:03.868 INFO:tasks.workunit.client.0.smithi023.stderr:++ /home/ubuntu/cephtest/mnt.0/client.0/tmp/tmp/../pjd-fstest-20090130-RC/tests/chmod/../../fstest stat fstest_e4841eea1a6b4fc7067ae31d4f7dbf1a ctime 2018-03-13T03:36:03.868 INFO:tasks.workunit.client.0.smithi023.stderr:+ ctime2=1520912163 2018-03-13T03:36:03.868 INFO:tasks.workunit.client.0.smithi023.stderr:+ test_check 1520912163 -lt 1520912163 2018-03-13T03:36:03.868 INFO:tasks.workunit.client.0.smithi023.stderr:+ '[' 1520912163 -lt 1520912163 ']' 2018-03-13T03:36:03.868 INFO:tasks.workunit.client.0.smithi023.stderr:+ echo 'not ok 27'
Updated by Zheng Yan about 6 years ago
yes, it looks like that 'sleep 1' slept less than 1 second. probably caused by changes in RC kernel
2018-03-09 21:03:51.124 7f895b510700 3 client.4408 ll_link 0x10000000347.head to 0x10000000343.head fstest_2986a053de976940aec2ea0ba5883209 ... 2018-03-09 21:03:51.128 7f895b510700 3 client.4408 link(#0x10000000347, #0x10000000343/fstest_2986a053de976940aec2ea0ba5883209) = 0 ... 2018-03-09 21:03:51.930 7f895b510700 3 client.4408 ll_unlink 0x10000000343.head fstest_2986a053de976940aec2ea0ba5883209 2018-03-09 21:03:51.930 7f895b510700 10 client.4408 _getattr mask AsXs issued=1 2018-03-09 21:03:51.930 7f895b510700 3 client.4408 may_delete 0x55e0b2870b00 = 0 2018-03-09 21:03:51.930 7f895b510700 3 client.4408 _unlink(0x10000000343 fstest_2986a053de976940aec2ea0ba5883209 uid 0 gid 0)
Updated by Zheng Yan almost 6 years ago
should close this if it does not happen again
Updated by Patrick Donnelly almost 6 years ago
- Target version changed from v13.0.0 to v13.2.0
- Component(FS) Client, MDS added
Updated by Patrick Donnelly almost 6 years ago
- Target version changed from v13.2.0 to v14.0.0
- Backport set to mimic,luminous
- Labels (FS) qa added
Updated by Patrick Donnelly about 5 years ago
- Target version changed from v14.0.0 to v15.0.0
Actions