Project

General

Profile

Actions
Copy link

Bug #23327

open

qa: pjd test sees wrong ctime after unlink

Added by Patrick Donnelly about 6 years ago. Updated about 5 years ago.

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

From: http://pulpito.ceph.com/yuriw-2018-03-09_16:22:21-fs-wip-yuriw-master-3.8.18-distro-basic-smithi/2271692/

This test: https://github.com/pjd/pjdfstest/blob/d379e7fd28e9075c2d816287bf4b321b8e13a16a/tests/unlink/00.t#L50-L58

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.

Actions
Copy link
 #1

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'
Actions
Copy link
 #2

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)
Actions
Copy link
 #3

Updated by Zheng Yan almost 6 years ago

should close this if it does not happen again

Actions
Copy link
 #5

Updated by Patrick Donnelly almost 6 years ago

  • Target version changed from v13.0.0 to v13.2.0
  • Component(FS) Client, MDS added
Actions
Copy link
 #6

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
Actions
Copy link
 #7

Updated by Patrick Donnelly about 5 years ago

  • Target version changed from v14.0.0 to v15.0.0
Actions
Copy link
 #8

Updated by Patrick Donnelly about 5 years ago

  • Target version deleted (v15.0.0)
Actions
Copy link

Also available in: Atom PDF