| Summary: | Seeing lots of error message "JournalPlayer: unexpected tag in journal entry" while renaming snapshot | ||||||||
|---|---|---|---|---|---|---|---|---|---|
| Product: | Red Hat Ceph Storage | Reporter: | Tanay Ganguly <tganguly> | ||||||
| Component: | RBD | Assignee: | Jason Dillaman <jdillama> | ||||||
| Status: | CLOSED WORKSFORME | QA Contact: | ceph-qe-bugs <ceph-qe-bugs> | ||||||
| Severity: | medium | Docs Contact: | |||||||
| Priority: | unspecified | ||||||||
| Version: | 2.0 | CC: | ceph-eng-bugs, jdillama, kdreyer, kurs, tganguly | ||||||
| Target Milestone: | rc | ||||||||
| Target Release: | 2.0 | ||||||||
| Hardware: | x86_64 | ||||||||
| OS: | Linux | ||||||||
| Whiteboard: | |||||||||
| Fixed In Version: | Doc Type: | Bug Fix | |||||||
| Doc Text: | Story Points: | --- | |||||||
| Clone Of: | Environment: | ||||||||
| Last Closed: | 2016-05-06 19:01:47 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: | |||||||
| Attachments: |
|
||||||||
I haven't been able to recreate this with 10.1.0 (nor current upstream master). Can you please recreate with "debug journaler = 20" / "debug rbd = 20" in your ceph.conf and attach the logs? Unable to reproduce in the latest 10.1.1.1 Build. Will Close it after few more regression test. Sounds good -- thanks. @Tanay: Have you had a chance to re-run the test and are you comfortable closing this ticket? Jason, Will update the BUG soon. Jason,
While reproducing this Bug i am hitting a crash.
rbd image 'testing2':
size 102400 MB in 25600 objects
order 22 (4096 kB objects)
block_name_prefix: rbd_data.10af238e1f29
format: 2
features: layering, exclusive-lock, object-map, fast-diff, deep-flatten, journaling
flags:
journal: 10af238e1f29
mirroring state: disabled
Steps:
1. Firstly i am running IO on an RBD Image.
rbd bench-write -p None --image testing2 --io-size 10240 --io-pattern rand
2, While step 1 is happening i am renaming the already created snapshot.
for i in {1..100}; do rbd snap rename None/testing2@snappy$i None/testing2@snap$i; done
Both renaming and bench-write is crashing ( This happened on 2nd iteration )
PFA, both logs (bench-write.log and renaming_snap.log)
Note: I am unable to reproduce the original issue.
Created attachment 1154724 [details]
rbd bench crash
Created attachment 1154725 [details]
renaming snap crash
Marking this BUG as CLOSED as i am unable to reproduce it with latest build. For Comment7 i have opened a new ticket after discussion with Jason. https://bugzilla.redhat.com/show_bug.cgi?id=1333950 |
Description of problem: Seeing lots of Error message while trying to rename a Clone, when primary Image is writing some IO Version-Release number of selected component (if applicable): ceph version 10.1.0-1 How reproducible: Steps to Reproduce: 1.Create an Image with all features enabled. rbd image 'testing2': size 10240 MB in 2560 objects order 22 (4096 kB objects) block_name_prefix: rbd_data.5fe8238e1f29 format: 2 features: layering, exclusive-lock, object-map, fast-diff, deep-flatten, journaling flags: journal: 5fe8238e1f29 mirroring state: disabled 2.Create 100 Snapshot on top the image. 3.Start IO on the parent volume, rbd bench-write -p Tanay-RBD --image testing2 --io-size 10240 --io-pattern rand 4.While IO is going on, try to rename all the 100 snapshot. Actual results: When initially i started the renaming of the snapshot, i saw lock_owner message popping. Check the lock, it was held by rbd bench-write rbd lock list Tanay-RBD/testing2 There is 1 exclusive lock on this image. Locker ID Address client.25493 auto 139675557707120 10.8.128.46:0/2255449993 Then i stopped the Write process, i.e. killed the IO. After that i am seeing the lock owner changed but the renaming failed throwing these error message. Expected results: There should not be any error message. Additional info: ---------------------------------------------------------------------------- ---------------------------------------------------------------------------- 2016-04-06 09:30:45.176374 7f42b8cf6700 -1 JournalPlayer: unexpected tag in journal entry: Entry[tag_tid=102, entry_tid=27966, data size=10270] 2016-04-06 09:30:45.499403 7f42b8cf6700 -1 JournalPlayer: unexpected tag in journal entry: Entry[tag_tid=102, entry_tid=27966, data size=10270] 2016-04-06 09:30:45.817712 7f42b8cf6700 -1 JournalPlayer: unexpected tag in journal entry: Entry[tag_tid=102, entry_tid=27966, data size=10270] 2016-04-06 09:30:46.134774 7f42b8cf6700 -1 JournalPlayer: unexpected tag in journal entry: Entry[tag_tid=102, entry_tid=27966, data size=10270] 2016-04-06 09:30:46.451229 7f42b8cf6700 -1 JournalPlayer: unexpected tag in journal entry: Entry[tag_tid=102, entry_tid=27966, data size=10270] 2016-04-06 09:30:46.767731 7f42b8cf6700 -1 JournalPlayer: unexpected tag in journal entry: Entry[tag_tid=102, entry_tid=27966, data size=10270] 2016-04-06 09:30:47.186626 7f42b8cf6700 -1 JournalPlayer: unexpected tag in journal entry: Entry[tag_tid=102, entry_tid=27966, data size=10270] 2016-04-06 09:30:47.503329 7f42b8cf6700 -1 JournalPlayer: unexpected tag in journal entry: Entry[tag_tid=102, entry_tid=27966, data size=10270] 2016-04-06 09:30:47.818182 7f42b8cf6700 -1 JournalPlayer: unexpected tag in journal entry: Entry[tag_tid=102, entry_tid=27966, data size=10270] 2016-04-06 09:30:48.169025 7f42b8cf6700 -1 JournalPlayer: unexpected tag in journal entry: Entry[tag_tid=102, entry_tid=27966, data size=10270] 2016-04-06 09:30:48.484491 7f42b8cf6700 -1 JournalPlayer: unexpected tag in journal entry: Entry[tag_tid=102, entry_tid=27966, data size=10270] 2016-04-06 09:30:48.801480 7f42b8cf6700 -1 JournalPlayer: unexpected tag in journal entry: Entry[tag_tid=102, entry_tid=27966, data size=10270] 2016-04-06 09:30:49.118825 7f42b8cf6700 -1 JournalPlayer: unexpected tag in journal entry: Entry[tag_tid=102, entry_tid=27966, data size=10270] 2016-04-06 09:30:49.435677 7f42b8cf6700 -1 JournalPlayer: unexpected tag in journal entry: Entry[tag_tid=102, entry_tid=27966, data size=10270] 2016-04-06 09:30:49.751402 7f42b8cf6700 -1 JournalPlayer: unexpected tag in journal entry: Entry[tag_tid=102, entry_tid=27966, data size=10270] 2016-04-06 09:30:50.067856 7f42b8cf6700 -1 JournalPlayer: unexpected tag in journal entry: Entry[tag_tid=102, entry_tid=27966, data size=10270] 2016-04-06 09:30:50.486481 7f42b8cf6700 -1 JournalPlayer: unexpected tag in journal entry: Entry[tag_tid=102, entry_tid=27966, data size=10270] 2016-04-06 09:30:50.801566 7f42b8cf6700 -1 JournalPlayer: unexpected tag in journal entry: Entry[tag_tid=102, entry_tid=27966, data size=10270] 2016-04-06 09:30:51.118479 7f42b8cf6700 -1 JournalPlayer: unexpected tag in journal entry: Entry[tag_tid=102, entry_tid=27966, data size=10270] 2016-04-06 09:30:51.434843 7f42b8cf6700 -1 JournalPlayer: unexpected tag in journal entry: Entry[tag_tid=102, entry_tid=27966, data size=10270] 2016-04-06 09:30:51.750799 7f42b8cf6700 -1 JournalPlayer: unexpected tag in journal entry: Entry[tag_tid=102, entry_tid=27966, data size=10270] 2016-04-06 09:30:52.069363 7f42b8cf6700 -1 JournalPlayer: unexpected tag in journal entry: Entry[tag_tid=102, entry_tid=27966, data size=10270] 2016-04-06 09:30:52.385749 7f42b8cf6700 -1 JournalPlayer: unexpected tag in journal entry: Entry[tag_tid=102, entry_tid=27966, data size=10270]