Mantis Bug Tracker

View Issue Details Jump to Notes ] Issue History ] Print ]
IDProjectCategoryView StatusDate SubmittedLast Update
0000434FlexRAID Transparent RAID[All Projects] Generalpublic2016-11-28 10:532017-01-10 03:08
Reporteradridolf 
Assigned ToBrahim 
PrioritynormalSeverityminorReproducibilityalways
StatusresolvedResolutionfixed 
PlatformWindowsOSWindows Server 2012 R2OS Version
Summary0000434: Mercurial push does not work
DescriptionI use Mercurial for version management in various project. While cloning from a local drive to the storage pool seems to work, I can not push changesets to existing repositories on the storage pool.
When trying this, I see a lot of "[WARN]:[OnSetEndOfFile] SetLengthByHandle" warnings in the FlexRAID.nzfs.log; it looks to me as if the changed project files (from the latest commit) are actually copied, but the final update of the changelog/manifest fails (the .dirstate* and 00manifest.i files reported in the log below).
Although I use ReFS which does not allow hard links (which are used by Mercurial), this issue is not directly caused by the file system, as non-FlexRAID ReFS drives work fine.
Steps To Reproduce1. "hg clone" a particular Mercurial project to the Storage Pool
2. Commit changes to a new local changeset
3. "hg push" from local repository to the older clone at the storage pool
-> Occasionally an access denied error is reported by Mercurial, but in any case the older repository is not updated
Additional InformationFor details about the setup please look at my previously reported issue ("Moving folder just deletes them").
Full error messages look like this:

[2016-10-25 14:46:00.049393][3356] [WARN]:[OnSetEndOfFile] SetLengthByHandle: error=5, msg=Error code=5 - Message=Input/output error
            \Store\Programming\Projects\AdvancedPictureProcessor\.hg\.dirstate-_r7am8 -> [HGST1 (Data)]::[Partition1]\Store\Programming\Projects\AdvancedPictureProcessor\.hg\.dirstate-_r7am8

[2016-10-25 14:47:07.612186][1936] [WARN]:[OnSetEndOfFile] SetLengthByHandle: error=5, msg=Error code=5 - Message=Input/output error
            \Store\Programming\Projects\AdvancedPictureProcessor\.hg\store\00manifest.i -> [HGST1 (Data)]::[Partition1]\Store\Programming\Projects\AdvancedPictureProcessor\.hg\store\00manifest.i

[2016-10-25 14:47:34.918969][3288] [WARN]:[OnSetEndOfFile] SetLengthByHandle: error=5, msg=Error code=5 - Message=Input/output error
            \Store\Programming\Projects\AdvancedPictureProcessor\.hg\.dirstate-ptdsoq -> [HGST1 (Data)]::[Partition1]\Store\Programming\Projects\AdvancedPictureProcessor\.hg\.dirstate-ptdsoq

[2016-10-25 14:54:19.143719][2472] [WARN]:[OnSetEndOfFile] SetLengthByHandle: error=5, msg=Error code=5 - Message=Input/output error
            \Store\Programming\Projects\DynDNS\.hg\store\00manifest.i -> [HGST1 (Data)]::[Partition1]\Store\Programming\Projects\DynDNS\.hg\store\00manifest.i

[2016-10-25 14:56:08.371430][2448] [WARN]:[OnSetEndOfFile] SetLengthByHandle: error=5, msg=Error code=5 - Message=Input/output error
            \Store\Programming\Projects\AdvancedPictureProcessor\.hg\store\00manifest.i -> [HGST1 (Data)]::[Partition1]\Store\Programming\Projects\AdvancedPictureProcessor\.hg\store\00manifest.i

[2016-10-25 14:59:23.096542][5084] [WARN]:[OnSetEndOfFile] SetLengthByHandle: error=5, msg=Error code=5 - Message=Input/output error
            \Store\Programming\Projects\AdvancedPictureProcessor\.hg\store\00manifest.i -> [HGST1 (Data)]::[Partition1]\Store\Programming\Projects\AdvancedPictureProcessor\.hg\store\00manifest.i

TagsNo tags attached.
tRAID Version 1.0
Attached Fileslog file icon flexraid_mercurial.log [^] (28,008 bytes) 2017-01-06 20:16
log file icon hg_clone.log [^] (523,145 bytes) 2017-01-07 16:03
log file icon hg_push.log [^] (762,022 bytes) 2017-01-07 16:03
zip file icon local.zip [^] (7,048 bytes) 2017-01-07 16:12
zip file icon pool.zip [^] (5,957 bytes) 2017-01-07 16:12
log file icon log_jan09.log [^] (872,897 bytes) 2017-01-09 13:44
log file icon mercurial_working.log [^] (935,452 bytes) 2017-01-09 16:25
log file icon msproperties.log [^] (62,336 bytes) 2017-01-09 18:08
png file icon FileStatBroken.PNG [^] (27,075 bytes) 2017-01-09 18:52


txt file icon ads_manual.txt [^] (6,426 bytes) 2017-01-09 18:52 [Show Content]

- Relationships

-  Notes
(0001593)
Brahim (manager)
2017-01-06 19:22

These errors are security related. Permission is being denied for those operations.
Do you happen to have a fuller log which chose the "OnOpenFile" statements for those entries?
(0001597)
adridolf (reporter)
2017-01-06 20:20

It is the only error I got. I uploaded a more complete segment of the log containing lots of those messages (which I created trying around when I thought of this as a connectivity problem).

I tried to increase the logging level based on your explanation:
http://wiki.flexraid.com/2011/03/26/how-to-enable-more-verbose-logging/ [^]

However, I do not have a logging.options.txt, so I fear this guide is outdated.
(0001600)
Brahim (manager)
2017-01-07 03:04

Log level setting in tRAID is done in one of two ways:

1. As explained here: http://wiki.flexraid.com/2013/06/27/changing-log-levels-in-transparent-raid/ [^]

2. Through the Web UI.
In the Web UI, right-click on the host icon and choose to edit. In the panel shown, you will see a section to change the log level.
Note that there is a bug in that the setting does not stick at time, which has been fixed for the next build.
However, saving the host config, will reset the log level live (no need to stop the pool or restart anything).
(0001622)
adridolf (reporter)
2017-01-07 16:12

Managed to change the log level to trace and did the following test scenario:
- Created a new repository with 1 file (step1.txt) locally
- Cloned this repository to the storage pool (folder /testclone)
- Renamed the folder on the pool (testclone to testpush) to know when the log for cloning ends
- Added a second file to the local repository (step2.txt) and committed locally.
- Pushed the changes to the repository on the pool (in the testpush folder).

Pushing was reported as successful in the Mercurial GUI, but was not successful in reality (but step2.txt.i is present in the .hg/store/data folder, so the copying of the changed files worked).

I added the log of the cloning step (hg_clone.log) and the log of the pushing step (hg_push.log). In addition, I added the source (local) and cloned (on the pool) repositories (local.zip and pool.zip).

Thanks for your help!
(0001623)
adridolf (reporter)
2017-01-07 16:14

Side note: No access denied messages in Mercurial throughout this test
(0001660)
adridolf (reporter)
2017-01-09 13:46

Sorry, no success. Cloned to test10clone, renamed to test10push, then pushed to test10push (so you can again distinguish both steps).

Log has been attached (log_jan09.log)
(0001667)
adridolf (reporter)
2017-01-09 16:24

This works during a quick test. "hg verify" is also successful. I will conduct more sophisticated tests in the evening.

Thank you very much for fixing this!

I appended logs for the (successful) process, in case you're interested (mercurial_working.log, folder names test12clone and test12push).

During cutting this section out of the log, I stumbled over another frequent warning (I also observed this frequently before, for files and folder not related to mercurial):

[2017-01-09 17:07:36.498878][3688] [WARN]:[OnGetFileInfo] INVALID_HANDLE_VALUE: error=2, msg=Error code=2 - Message=No such file or directory
            \test12clone:ms-properties -> [HGST1 (Data)]::[Partition1]\test12clone:ms-properties

[2017-01-09 17:07:36.514880][3688] [WARN]:[OnGetFileInfo] INVALID_HANDLE_VALUE: error=2, msg=Error code=2 - Message=No such file or directory
            \test12clone:ms-properties -> [HGST1 (Data)]::[Partition1]\test12clone:ms-properties

The file system seems to have problems with those strange ms-properties "files" or whatever, which are not present or visible from a Windows system. Can you provide some insight on that? Should I just ignore it or would it be useful to open a new issue for that ...?
(0001668)
Brahim (manager)
2017-01-09 17:01

"[WARN]:[OnGetFileInfo] INVALID_HANDLE_VALUE: error=2, msg=Error code=2 - Message=No such file or directory
            \test12clone:ms-properties -> [HGST1 (Data)]::[Partition1]\test12clone:ms-properties"

Those might be non-issue. The program might be merely looking for an alternate data stream content, which does not exist.
To validate, check the file for ADS: https://blogs.technet.microsoft.com/askcore/2013/03/24/alternate-data-streams-in-ntfs/ [^]

Do the check on both the source file (outside of the pool) and on the file in the pool.
This is to ensure that if the file outside of the pool had an ADS, it got copied with the file in the pool.

Old versions of ReFS do not support ADS. Your version should be fine though if 2012 R2.
Per Wikipedia: "Support for alternate data streams was initially not implemented in ReFS. In Windows 8.1 64-bit and Server 2012 R2 the file system reacquired support for alternate data streams, with lengths of up to 128K".
(0001669)
adridolf (reporter)
2017-01-09 18:21

Mercurial still survives my tests, so this should be dealt with. :-)

Regarding the ms-properties issue:
I can cause the WARN message by simply creating a file or folder on the storage pool (no source file involved). In the msproperties.log I just created a folder test41 in the pool root and the added a subfile test42.txt. (Via Remote Desktop, so no network share involved). Note that I get the warning for both and even for the "New Text Document.txt" before renaming it. (During earlier test the same happened for "New folder")

I used the right-click->New->Folder/Text file context menu.

Maybe there is also connection to issue 433 (creating shortcuts, http://bug.flexraid.com/view.php?id=433 [^]), where I also get ms-properties error and the following regarding the Zone.Identifier (I did not append a log on that):

[2017-01-09 19:17:54.124496][0784] [WARN]:[OnGetFileInfo] INVALID_HANDLE_VALUE: error=2, msg=Error code=2 - Message=No such file or directory
            \Test.url:Zone.Identifier -> [HGST1 (Data)]::[Partition1]\Test.url:Zone.Identifier
(0001671)
adridolf (reporter)
2017-01-09 18:52
edited on: 2017-01-09 18:53

Further notes:
1. Latest update broke my file statistics windows (FileStatBroken.png, maybe coincidence)
2. I can write ADS to the Storage Pool and the information sticks (confirming my ReFS version is capable of it):
Command:
> Set-Content -Path P:\a.txt -Stream "ForthStream"
...
Results:
> Get-Item -Path P:\a.txt -stream *


   FileName: P:\a.txt

Stream Length
------ ------
:$DATA 3
ForthStream 10
SecondStream 5
ThirdStream 36

However, I still get a warning (look for ForthStream in ads_manual.txt). So maybe this really is something we do not have to care about, since the information seems to be there...?

(0001672)
Brahim (manager)
2017-01-10 02:52
edited on: 2017-01-10 02:53

1. Don't combine issues (File Stats issue) under the same bug. Open a new report for any other issue than the one being resolved here.

2. Based on below, your file system supports ADS just fine. Further, those warnings are normal. The client program was just looking for an ADS that simply isn't there. Client programs will almost always try to open an ADS blindly rather than enumerate for its presence first. It is a simpler call.

[2017-01-09 19:42:16.902975][3376][OnOpenFile] \Store\a.txt:ForthStream
[2017-01-09 19:42:16.902976][3376] [OnOpenFile] \Store\a.txt:ForthStream -> [HGST1 (Data)]::[Partition1]\Store\a.txt:ForthStream - access=8590983299, mode=317656796
[2017-01-09 19:42:16.902976][3376] access=[SYNCHRONIZE], mode=[SHARE_WRITE]
[2017-01-09 19:42:16.902976][3376] Attributes=[ARCHIVE]
[2017-01-09 19:42:16.902976][3376] [OnOpenFile] (handle=992)
[2017-01-09 19:42:16.902977][3376] [OnOpenFile] => Exited...

(0001673)
Brahim (manager)
2017-01-10 03:08

Thanks for the report and confirming the fix.
This is resolved for the next release.

- Issue History
Date Modified Username Field Change
2016-11-28 10:53 adridolf New Issue
2017-01-06 19:22 Brahim Note Added: 0001593
2017-01-06 19:22 Brahim Assigned To => Brahim
2017-01-06 19:22 Brahim Status new => feedback
2017-01-06 20:16 adridolf File Added: flexraid_mercurial.log
2017-01-06 20:20 adridolf Note Added: 0001597
2017-01-06 20:20 adridolf Status feedback => assigned
2017-01-07 03:04 Brahim Note Added: 0001600
2017-01-07 03:04 Brahim Status assigned => feedback
2017-01-07 16:03 adridolf File Added: hg_clone.log
2017-01-07 16:03 adridolf File Added: hg_push.log
2017-01-07 16:12 adridolf Note Added: 0001622
2017-01-07 16:12 adridolf Status feedback => assigned
2017-01-07 16:12 adridolf File Added: local.zip
2017-01-07 16:12 adridolf File Added: pool.zip
2017-01-07 16:14 adridolf Note Added: 0001623
2017-01-08 23:56 Brahim Status assigned => feedback
2017-01-09 13:44 adridolf File Added: log_jan09.log
2017-01-09 13:46 adridolf Note Added: 0001660
2017-01-09 13:46 adridolf Status feedback => assigned
2017-01-09 15:52 Brahim Status assigned => feedback
2017-01-09 16:24 adridolf Note Added: 0001667
2017-01-09 16:24 adridolf Status feedback => assigned
2017-01-09 16:25 adridolf File Added: mercurial_working.log
2017-01-09 17:01 Brahim Note Added: 0001668
2017-01-09 17:01 Brahim Status assigned => feedback
2017-01-09 18:08 adridolf File Added: msproperties.log
2017-01-09 18:21 adridolf Note Added: 0001669
2017-01-09 18:21 adridolf Status feedback => assigned
2017-01-09 18:52 adridolf Note Added: 0001671
2017-01-09 18:52 adridolf File Added: FileStatBroken.PNG
2017-01-09 18:52 adridolf File Added: ads_manual.txt
2017-01-09 18:53 adridolf Note Edited: 0001671 View Revisions
2017-01-10 02:52 Brahim Note Added: 0001672
2017-01-10 02:53 Brahim Note Edited: 0001672 View Revisions
2017-01-10 03:08 Brahim Note Added: 0001673
2017-01-10 03:08 Brahim Status assigned => resolved
2017-01-10 03:08 Brahim Resolution open => fixed


Copyright © 2000 - 2010 MantisBT Group
Powered by Mantis Bugtracker