Arm64 build for Windows

[unintended-consequences]

The associated forum post URL from https://forum.rclone.org

https://forum.rclone.org/t/arm-64-bit-for-windows/27559/3

What is your current rclone version (output from rclone version)?

rclone v1.58.0-beta.5896.f9321fccb

What problem are you are trying to solve?

Trying to get a native build for Microsoft Surface Pro X (running on Microsoft SQ1 ARM processor)

How do you think rclone should be changed to solve that?

The beta build that ncw posted in the forum works!

How to use GitHub

• Please use the 👍 reaction to show that you are affected by the same issue.
• Please don't comment if you have no relevant information to add. It's just extra noise for everyone subscribed to this issue.
• Subscribe to receive notifications on status change and new comments.

[ivandeex]

The latest release of golang can cross-compile for windows/arm64,
but the CI infrastructure is not completely ready for that step yet.
Can't find any mentions of windows/arm64 on the github runners page
https://docs.github.com/en/actions/using-github-hosted-runners/about-github-hosted-runners#supported-software
The WinFSP project does not yet release install packages for windows/arm64
Don't yet know if chocolatey release dev packages for the platform

[ncw]

It will be relatively straight forward to build a cross compiled version of rclone which will not have rclone mount support but otherwise be fully functional.

In fact @unintended-consequences tested a version of that for me in the forum.

I think we should probably do that for the moment while we wait for WinFSP and GitHub actions to catch up.

[ncw]

I had a go at that... If it goes to plan a windows/arm64 build will end up here...

v1.58.0-beta.5900.2346497f8.fix-5828-windows-arm64 on branch fix-5828-windows-arm64 (uploaded in 15-30 mins)

[ncw]

OK here is the next attempt!

v1.58.0-beta.5903.aa406ce6b.fix-5828-windows-arm64 on branch fix-5828-windows-arm64 (uploaded in 15-30 mins)

[ncw]

Looks like that build OK. Any takers with windows/arm64 to try this binary?

https://beta.rclone.org/branch/fix-5828-windows-arm64/v1.58.0-beta.5903.aa406ce6b.fix-5828-windows-arm64/rclone-v1.58.0-beta.5903.aa406ce6b.fix-5828-windows-arm64-windows-arm64.zip

[ncw]

I've merged this to master now which means it will be in the latest beta in 15-30 minutes and we will officially support windows/arm64 binaries in v1.58 but without WinFsp/mount support for the moment.

[ncw]

If anyone with a windows/arm64 device would like to try this binary which should support rclone mount and the new WinFSP which supports arm64 I'd be very interested in the results.

v1.59.0-beta.6084.8920feefc.fix-cmount-windows-nocgo on branch fix-cmount-windows-nocgo

[Jovines]

If anyone with a windows/arm64 device would like to try this binary which should support rclone mount and the new WinFSP which supports arm64 I'd be very interested in the results.

v1.59.0-beta.6084.8920feefc.fix-cmount-windows-nocgo on branch fix-cmount-windows-nocgo

I am trying your version using Windows ARM64. It does not seem to be working properly, and the disk is displayed after being mounted, but is kept waiting and cannot be viewed.

Just like this, Q is the disk I mounted with rclone.

I used WinFsp 2022+ARM64 Beta2.

[ncw]

@Jovines

Thanks for testing.

Can you attach a log made like this please?

rclone mount ... -vv --debug-fuse --log-file rclone.log

[hellvy-github]

Hello, I have the same result as Jovines, the disk is displayed, but is kept waiting and cannot be viewed. The rclone console is stuck after enter password and forced restart needed. Sometimes I've got no drive at all, but rclone console exit to prompt and working.

Here's log file when drive is displayed but can not be viewed. I'm looking forward to use this feature on my surface pro x, Thank you :)

I'm using rclone-v1.59.0-beta.6089.cdb40336b.fix-cmount-windows-nocgo-windows-arm64 and winfsp-1.11.22176
rclone-withdrive.log

[ncw]

@hellvy-github for completeness sake, can you try the latest beta - this code has been merged to master now. I'm not sure it will make a difference but we'll all be trying the same thing anyway.

It looks like it is working in the log - at least I can't see any obvious errors.

How are you starting rclone? Just running as your user in a command prompt? That would be recommended for testing.

It might be worth supplying a specific drive name or a folder to mount on to see if that makes a difference.

[hellvy-github]

Hello, @ncw, thank you for your reply. I've tried the latest beta build, still have no luck. I've disabled windows firewall for testing and tried few mount options. I've attached some screen and log files for you guys to investigate.

Sorry for messing test options. It's my first time trying rclone mount. Just rclone copy all the time before.

rclone-20220629-mount-drive.log
rclone-20220629-network-share-3.log
rclone-20220629-network-share-2.log
rclone-20220629-mount-dir.log
rclone-20220629-network-share.log

[hellvy-github]

Hello, I've compared log file from working Intel PC with log from Surface Pro X.
Log file from working Intel PC,

...
2022/07/01 20:38:05 DEBUG : Google drive root '': root_folder_id = "0AMMeTj1Fmu7pUk9PVA" - save this in the config to speed up startup
2022/07/01 20:38:06 NOTICE: Assigning drive letter "Z:"
2022/07/01 20:38:06 DEBUG : Network mode mounting is disabled
2022/07/01 20:38:06 DEBUG : Mounting on "Z:" ("gd")
2022/07/01 20:38:06 DEBUG : Google drive root '': Mounting with options: ["-o" "attr_timeout=1" "-o" "debug" "-o" "uid=-1" "-o" "gid=-1" "--FileSystemName=rclone" "-o" "volname=gd"]
2022/07/01 20:38:06 DEBUG : Google drive root '': Init:
2022/07/01 20:38:06 DEBUG : Google drive root '': >Init:
2022/07/01 20:38:06 DEBUG : /: Statfs:
2022/07/01 20:38:06 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:307067065061 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2022/07/01 20:38:06 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2022/07/01 20:38:06 DEBUG : /: >Getattr: errc=0
2022/07/01 20:38:06 DEBUG : /: Readlink:
2022/07/01 20:38:06 DEBUG : /: >Readlink: linkPath="", errc=-40
The service rclone has been started.
rclone[TID=05e8]: FFFF858B8C34D050: >>QueryVolumeInformation
2022/07/01 20:38:06 DEBUG : /: Statfs:
2022/07/01 20:38:06 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:307067065061 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
rclone[TID=05e8]: FFFF858B8C34D050: <<QueryVolumeInformation IoStatus=0[0] VolumeInfo={TotalSize=477e9:f92e5000, FreeSize=40000:0, VolumeLabel="gd"}
rclone[TID=05e8]: FFFF858B8C2C2A90: >>Create [UT---C] "", FILE_OPEN, CreateOptions=21, FileAttributes=10, Security=NULL, AllocationSize=0:0, AccessToken=00000000000005BC[PID=820], DesiredAccess=100000, GrantedAccess=0, ShareAccess=3
2022/07/01 20:38:06 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2022/07/01 20:38:06 DEBUG : /: >Getattr: errc=0
...

Log file from Surface Pro X

...
2022/07/03 09:14:01 DEBUG : Google drive root '': 'root_folder_id = 0AMMeTj1Fmu7pUk9PVA' - save this in the config to speed up startup
2022/07/03 09:14:01 NOTICE: Assigning drive letter "Z:"
2022/07/03 09:14:01 DEBUG : Network mode mounting is disabled
2022/07/03 09:14:01 DEBUG : Mounting on "Z:" ("gd")
2022/07/03 09:14:01 DEBUG : Google drive root '': Mounting with options: ["-o" "attr_timeout=1" "-o" "debug" "-o" "uid=-1" "-o" "gid=-1" "--FileSystemName=rclone" "-o" "volname=gd"]
2022/07/03 09:14:02 DEBUG : Google drive root '': Init:
2022/07/03 09:14:02 DEBUG : Google drive root '': >Init:
2022/07/03 09:14:02 DEBUG : /: Statfs:
2022/07/03 09:14:02 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:307067065061 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2022/07/03 09:14:02 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2022/07/03 09:14:02 DEBUG : /: >Getattr: errc=0
2022/07/03 09:14:02 DEBUG : /: Readlink:
2022/07/03 09:14:02 DEBUG : /: >Readlink: linkPath="", errc=-40
2022/07/03 09:14:02 DEBUG : /: Getxattr: name="non-existant-a11ec902d22f4ec49003af15282d3b00"
2022/07/03 09:14:02 DEBUG : /: >Getxattr: errc=-40, value=""
rclone[TID=3444]: FFFF868BEA915DD0: >>QueryVolumeInformation
2022/07/03 09:14:02 DEBUG : /: Statfs:
2022/07/03 09:14:02 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:307067065061 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
rclone[TID=3444]: FFFF868BEA915DD0: <<QueryVolumeInformation IoStatus=0[0] VolumeInfo={TotalSize=477e9:f92e5000, FreeSize=40000:0, VolumeLabel="gd"}
rclone[TID=3444]: FFFF868BECEDFDC0: >>Create [UT---C] "", FILE_OPEN, CreateOptions=21, FileAttributes=10, Security=NULL, AllocationSize=0:0, AccessToken=00000000000005BC[PID=2694], DesiredAccess=100000, GrantedAccess=0, ShareAccess=3
2022/07/03 09:14:02 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2022/07/03 09:14:02 DEBUG : /: >Getattr: errc=0
..

I've noticed some different in log files. While Intel PC got "The service rclone has been started." after "Readlink: linkPath="", errc=-40". Surface Pro X got "Getxattr: name="non-existant-a11ec902d22f4ec49003af15282d3b00"" instead.

Is there any clue from this? Is there anything to do with WinFsp?

Ps. rclone on Interl PC version is v1.55.1 while on Surface Pro X is v1.59.0-beta.6309.73e3bb09d.

[ncw]

I'm really not sure what is going on here. I think we are going to have to ask @billziss-gh for help. Those two startups don't look very different to me but the ARM64 one is missing the "The service rclone has been started." line which is suspicious.

The Getxattr: name="non-existant-a11ec902d22f4ec49003af15282d3b00" is from something probing to see if xattrs are supported.

[billziss-gh]

Unfortunately I am on vacation and unable to look into this in detail.

I had a brief look at the cgofuse code and it appears that it knows how to correctly load the ARM64 version of the WinFsp DLL. @ncw are you using the cgo or nocgo variant of cgofuse?

BTW, if you do not see the message: “The service rclone has been started.” then FUSE has not been started, which is definitely a problem.

[hellvy-github]

Hello @billziss-gh, thank you for checking this issue out. According to this comment of mine #5828 (comment), I think it's nocgo variant .

Thank you and have a great vacation :)

[ncw]

Unfortunately I am on vacation and unable to look into this in detail.

Enjoy your vacation :-)

I had a brief look at the cgofuse code and it appears that it knows how to correctly load the ARM64 version of the WinFsp DLL. @ncw are you using the cgo or nocgo variant of cgofuse?

We are now using the nocgo variant which has simplified a lot of the build infrastructure :-)

BTW, if you do not see the message: “The service rclone has been started.” then FUSE has not been started, which is definitely a problem.

OK.

[hellvy-github]

Hello, any update for this issue? Should we try cgo variant of cgofuse as @ivandeex mentioned? Is there something that surface pro x user with zero coding and low compiling experience can help?

[ncw]

@hellvy-github if you are able to compile go programs on the surface pro directly, then you'll be using CGO by default. So downloading the rclone source and just running go build -tags cmount should build it with CGO. You'll need the fuse header files and a C compiler so it isn't trivial to set up. There are some hints here: https://github.com/rclone/rclone/blob/master/bin/win-build.bat

[hellvy-github]

Thank you @ncw for your information, I'll try it asap.
Don't worry about compiler tools, I guess I have plenty. I have 2 variants of ninja, compiled by go and compiled by CC variant. I also have 3 variants of LLVM. The one come with Visual Studio I've installed, other one is binary installed because I don't know it already come with Visual Studio. And the one I manually compiled because I don't know it's the same tool I've already installed. I just don't know what ninja and LLVM actually are.

[hellvy-github]

Hello @ncw , I've tried building rclone form source and got this error..

C:_Silo_build\rclone>go build -trimpath -ldflags -s -tags cmount
runtime/cgo
In file included from _cgo_export.c:4:
cgo-gcc-export-header-prolog:25:55: error: '_check_for_64_bit_pointer_matching_GoInt' declared as an array with a negative size

C:_Silo_build\rclone>

But when I set CGO_ENABLED=0, It can build successfully but the same result when mount.

Do you have any idea about this error?

[ncw]

Try setting the env vars

CGO_CFLAGS="-arch arm64"
CGO_LDFLAGS="-arch arm64"

I think that the compiler might be being invoked as a 32 bit compiler.

[hellvy-github]

Hello, @ncw. When I tried compiling it again, there's no error

"cgo-gcc-export-header-prolog:25:55: error: '_check_for_64_bit_pointer_matching_GoInt' declared as an array with a negative size"

anymore, I don't know why. Then I can proceed to get other error. With or without adding CGO_CFLAGS and CGO_LDFLAGS, I got

go build -trimpath -ldflags -s -tags cmount
github.com/winfsp/cgofuse/fuse
In file included from _cgo_export.c:4:
cgo-gcc-export-header-prolog:43:34: error: redeclaration of 'go_hostGetattr' cannot add 'dllexport' attribute
host_cgo.go:322:12: note: previous declaration is here
cgo-gcc-export-header-prolog:44:34: error: redeclaration of 'go_hostReadlink' cannot add 'dllexport' attribute
host_cgo.go:323:12: note: previous declaration is here
......
......
cgo-gcc-export-header-prolog:61:34: error: redeclaration of 'go_hostFsync' cannot add 'dllexport' attribute
host_cgo.go:342:12: note: previous declaration is here
fatal error: too many errors emitted, stopping now [-ferror-limit=]

Here're some go env and variables I've set

C:_Silo_build\rclone-1.59.0-1>go env
set GOARCH=arm64
set GOHOSTARCH=arm64
set GOHOSTOS=windows
set GOVERSION=go1.18.4
set GCCGO=gccgo
set AR=ar
set CC=clang.exe
set CXX=clang.exe
set CGO_ENABLED=1
set CGO_CFLAGS=-g -O2 -arch arm64
set CGO_CXXFLAGS=-g -O2
set CGO_FFLAGS=-g -O2
set CGO_LDFLAGS=-g -O2 -arch arm64
set GOGCCFLAGS=-mthreads -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=C:_Silo\tmps\go-build3711696058=/tmp/go-build -gno-record-gcc-switches

clang -v
clang version 14.0.6
Target: arm64-pc-windows-msvc
Thread model: posix

Thank you.

[unintended-consequences]

Sorry, just checking in to see if there any further consideration for progress on rclone mount ?

[hellvy-github]

Hi @unintended-consequences, not much progress on my side due to lack of knowledge and free time. Still got same error but knowing that this error

cgo-gcc-export-header-prolog:25:55: error: '_check_for_64_bit_pointer_matching_GoInt' declared as an array with a negative size

and this

cgo-gcc-export-header-prolog:43:34: error: redeclaration of 'go_hostGetattr' cannot add 'dllexport' attribute
host_cgo.go:322:12: note: previous declaration is here

occurred in difference variant of LLVM's clang I used.

I tried to make the most of my free time by building rclone mount with different variant of clang at the same time. Ending with different errors for each variant. I think I should try to solve error one at a time.

[billziss-gh]

I am back from vacation and will be look at this in the next day or two. Sorry for the long delay.

[billziss-gh]

I set up a minimal development environment on a new Win11 ARM64 VM and was able to build the nocgo version of rclone.

When I run a command such as rclone mount xps:Projects X: (xps is an SFTP remote on my Windows laptop) I see that the X: drive is created, but it is not functional. It appears that Explorer is never able to open the root directory on the drive.

PROBLEMS

In my attempts to troubleshoot this problem I seem to have stumbled upon multiple other problems:

• Sometimes rclone exits immediately and does not create the drive at all. Other times it manages to create the drive, but as mentioned it does not function correctly. I suspect some sort of race on startup.

• Sometimes I get a warning/error about "poll_interval". Passing --poll_interval 0 seems to quieten this message.

• It is not clear to me how to get full debug logs from rclone. When I use -v --debug-fuse I seem to get the WinFsp debug logs. When I use -vv --debug-fuse I seem to get rclone's own debug logs. @ncw what is the proper way to invoke rclone to get full debug logs? (Ideally I would like to get both WinFsp and rclone debug logs if that is possible.)

• Unfortunately the Delve debugger does not currently support Windows/ARM64 so it is not possible to run rclone under the debugger.

SPECULATION

On a couple of runs with -v --debug-fuse I was able to get somewhat usable WinFsp debug logs. These showed that the drive was created properly and the system attempted to get information about the drive (QueryVolumeInformation) and then open its root directory (Create "\"). In at least one of those debug logs, rclone never returned from the Create "\" call.

This means that some system component was stuck waiting for the root directory of the drive to be opened. Naturally if a file system does not complete open requests, its drive appears non-functional.

[hellvy-github]

Hello @billziss-gh, It's great having you here and see practical investigation :) So you think the problem doesn't come from cgo and nocgo variant right?

I'd like to tell that I've sorted my testing procedure out and lead all of my 3 variants of clang to the same error which is

go build -trimpath -ldflags -s -tags cmount
github.com/winfsp/cgofuse/fuse
In file included from _cgo_export.c:4:
cgo-gcc-export-header-prolog:43:34: error: redeclaration of 'go_hostGetattr' cannot add 'dllexport' attribute
host_cgo.go:322:12: note: previous declaration is here
......
......
cgo-gcc-export-header-prolog:61:34: error: redeclaration of 'go_hostFsync' cannot add 'dllexport' attribute
host_cgo.go:342:12: note: previous declaration is here
fatal error: too many errors emitted, stopping now [-ferror-limit=]

And I can't do anything further, so I'll just sit here watching and hoping there's something I can help :)

[ncw]

I set up a minimal development environment on a new Win11 ARM64 VM and was able to build the nocgo version of rclone.

Thanks for having a look at this @billziss-gh

• Sometimes I get a warning/error about "poll_interval". Passing --poll_interval 0 seems to quieten this message.

You can ignore these - the are harmless

• It is not clear to me how to get full debug logs from rclone. When I use -v --debug-fuse I seem to get the WinFsp debug logs. When I use -vv --debug-fuse I seem to get rclone's own debug logs. @ncw what is the proper way to invoke rclone to get full debug logs? (Ideally I would like to get both WinFsp and rclone debug logs if that is possible.)

-vv --debug-fuse should be the right incantation to get both rclone debug logs and enable the WinFsp debug logs. The rclone debug logs can be quite noisy.

On a couple of runs with -v --debug-fuse I was able to get somewhat usable WinFsp debug logs. These showed that the drive was created properly and the system attempted to get information about the drive (QueryVolumeInformation) and then open its root directory (Create "\"). In at least one of those debug logs, rclone never returned from the Create "\" call.

This means that some system component was stuck waiting for the root directory of the drive to be opened. Naturally if a file system does not complete open requests, its drive appears non-functional.

It would be insteresting to see the -vv --debug-fuse logs here to see how far rclone got.

Running rclone with the --rc flag as well and then looking at http://localhost:5572/debug/pprof/goroutine?debug=1 will show what go routines are executing and where rclone is stuck which would be very useful info - that should help pinpoint the problem.

[billziss-gh]

SUMMARY

Investigation has shown that this issue is a result of two problems in the Golang runtime:

• The Golang runtime captures all Windows exceptions using AddVectoredExceptionHandler. Vectored Exception Handlers run prior to the regular Structured Exception Handlers in Windows. This means that Golang will see and consider fatal exceptions that are normal in the regular execution of a Windows program; such exceptions would have been handled just fine if SEH was allowed to run.

• The Windows ARM64 version of runtime.badsignal2 has a serious bug that results in an Access Violation crash in WriteFile.

I will report these problems to Golang and possibly also provide patches for them (if my CLA with Google is still valid).

IN DETAIL

badsignal2

I eventually found time to look into this problem again. After trying a couple of times with rclone I decided to try with the memfs sample from cgofuse and sure enough I was able to reproduce the problem. Under WinDbg I would get an Access Violation inside WriteFile with a minimal stack:

0:008> k
 # Child-SP          RetAddr               Call Site
00 00000086`77ffe450 00007ff7`5d1ffa38     KERNELBASE!WriteFile+0x3c
01 00000086`77ffe4b0 00000000`00000000     memfs+0x5fa38

This stack is not very useful as WinDbg does not understand the Golang symbol format and does not know how to walk the Golang stack.

Eventually I was able to figure out that the crash would happen within WinFsp's FspServiceLoop and specifically while calling the Windows API StartServiceCtrlDispatcherW. WinFsp uses this API to switch a process into a service if possible; the call is expected to fail in the case of running a FUSE file system from the command line, but this failure is benign.

At this point I had a bit of hair-pulling and even started doubting my tools: how did calling a Windows API in a non-Golang thread result in a Golang crash in WriteFile? Eventually it dawned on me that perhaps the WriteFile buffer might contain some useful information and I should try to see what is in it. I looked up the AArch64 calling convention, which says that registers x0-x7 are used for passing arguments. With this information and the WriteFile prototype we get:

BOOL WriteFile(
  [in]                HANDLE       hFile,
  [in]                LPCVOID      lpBuffer,
  [in]                DWORD        nNumberOfBytesToWrite,
  [out, optional]     LPDWORD      lpNumberOfBytesWritten,
  [in, out, optional] LPOVERLAPPED lpOverlapped
);

/*
 * x0 -> hFile
 * x1 -> lpBuffer
 * x2 -> nNumberOfBytesToWrite
 * x3 -> lpNumberOfBytesWritten
 * x4 -> lpOverlapped
 */

So what are the values of the registers at the time of the crash?

0:008> r
 x0=000000000000006c   x1=00007ff75d3759c0   x2=0000000000000036   x3=0000000000000007
 x4=0000000000000000   x5=00007ff75d3759c0   x6=00007ff75d203f10   x7=00007ffd95a46ad8
 x8=0000008677ffe480   x9=0000023efbe03c90  x10=00007ff7a7f42901  x11=0000000000000000
x12=00007ffd94eee7a0  x13=0000000000000007  x14=00007ffd959fe5a4  x15=00007ff75d1ffa60
x16=00007ffd915b9c60  x17=0000000000000000  x18=0000000000000000  x19=0000000000000007
x20=0000000000000000  x21=000000000000006c  x22=0000000000000000  x23=00007ffd95d2ba20
x24=00007ffd95d2ba28  x25=0000023efbe15150  x26=00007ff75d1ffa60  x27=00007ff75d308180
x28=0000000000000000   fp=0000008677ffe460   lr=00007ff75d1ffa38   sp=0000008677ffe450
 pc=00007ffd915b9c9c  psr=00000040 ---- EL0

So the crash happens because register x3 which is supposed to contain the pointer lpNumberOfBytesWritten contains the bogus value 7.

And just what does register x1 which contains the lpBuffer contain?

0:008> d x1
00007ff7`5d3759c0  72 75 6e 74 69 6d 65 3a-20 73 69 67 6e 61 6c 20  runtime: signal 
00007ff7`5d3759d0  72 65 63 65 69 76 65 64-20 6f 6e 20 74 68 72 65  received on thre
00007ff7`5d3759e0  61 64 20 6e 6f 74 20 63-72 65 61 74 65 64 20 62  ad not created b
00007ff7`5d3759f0  79 20 47 6f 2e 0a 00 00-00 00 00 00 00 00 00 00  y Go............
00007ff7`5d375a00  00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00  ................
00007ff7`5d375a10  00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00  ................
00007ff7`5d375a20  00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00  ................
00007ff7`5d375a30  00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00  ................

Aha! Now we are getting somewhere.

It looks like the Golang runtime has received a "bad signal" and is trying to say so on stderr. Let us look in the Golang source where this string is defined and used. We find it in setBadSignalMsg:

func setBadSignalMsg() {
	const msg = "runtime: signal received on thread not created by Go.\n"
	for i, c := range msg {
		badsignalmsg[i] = byte(c)
		badsignallen++
	}
}

So where is badsignalmsg used from? We find it in badsignal2:

TEXT runtime·badsignal2(SB),NOSPLIT,$16-0
	NO_LOCAL_POINTERS

	// stderr
	MOVD	runtime·_GetStdHandle(SB), R1
	MOVD	$-12, R0
	SUB	$16, RSP	// skip over saved frame pointer below RSP
	BL	(R1)
	ADD	$16, RSP

	// handle in R0 already
	MOVD	$runtime·badsignalmsg(SB), R1	// lpBuffer
	MOVD	$runtime·badsignallen(SB), R2	// lpNumberOfBytesToWrite
	MOVD	(R2), R2
	MOVD	R13, R3		// lpNumberOfBytesWritten
	MOVD	$0, R4			// lpOverlapped
	MOVD	runtime·_WriteFile(SB), R12
	SUB	$16, RSP	// skip over saved frame pointer below RSP
	BL	(R12)

	// Does not return.
	B	runtime·abort(SB)

	RET

Notice here how "R3" (really ARM64 x3) is initialized using a bogus value from "R13" (really ARM64 x13). This is what causes the Access Violation in WriteFile.

The fix for badsignal2 is to properly initialize x3.

initExceptionHandler

So we found the source of the crash, but the question remains: why does Golang think that it got a "bad signal" (not to mention that we are on Windows)?

Searching for badsignal2 reveals a few places where this routine is called. Importantly we find that sigtramp calls badsignal2 if there is no "current g" (i.e. this thread is not a Golang thread).

And just who calls sigtramp? A few places actually, but importantly one of the following: exceptiontramp, firstcontinuetramp, lastcontinuetramp.

So this looks like part of some generic exception handling that the Golang runtime sets up. Indeed we find that the Golang runtime sets it up in initExceptionHandler:

func initExceptionHandler() {
	stdcall2(_AddVectoredExceptionHandler, 1, abi.FuncPCABI0(exceptiontramp))
	if _AddVectoredContinueHandler == nil || GOARCH == "386" {
		// use SetUnhandledExceptionFilter for windows-386 or
		// if VectoredContinueHandler is unavailable.
		// note: SetUnhandledExceptionFilter handler won't be called, if debugging.
		stdcall1(_SetUnhandledExceptionFilter, abi.FuncPCABI0(lastcontinuetramp))
	} else {
		stdcall2(_AddVectoredContinueHandler, 1, abi.FuncPCABI0(firstcontinuetramp))
		stdcall2(_AddVectoredContinueHandler, 0, abi.FuncPCABI0(lastcontinuetramp))
	}
}

The initExceptionHandler uses AddVectoredExceptionHandler to add a Vectored Exception Handler. This use looks ill-advised. Windows components (and some third party applications and DLLs) regularly use Structured Exception Handling to report benign errrors, such as "Access Denied". Vectored Exception Handlers run prior to the regular Structured Exception Handlers in Windows. This means that the Golang runtime preempts the regular processing of benign errors and thinks that an unrecoverable error has happened.

Let's confirm our suspicion by re-running memfs all the way to StartServiceCtrlDispatcherW. We then set a breakpoint at RaiseException (bp KernelBase!RaiseException) and continue the program.

The debugger stops on entry to RaiseException. Let's examine our call stack:

0:009> k
 # Child-SP          RetAddr               Call Site
00 00000060`f85ff050 00007ffd`91fc3108     KERNELBASE!RaiseException
01 00000060`f85ff050 00007ffd`91fc30c0     RPCRT4!RpcpRaiseException+0x40
02 00000060`f85ff070 00007ffd`91f92208     RPCRT4!RpcRaiseException+0x20
03 00000060`f85ff090 00007ffd`92112d5c     RPCRT4!NdrpSendReceive+0x118
04 00000060`f85ff0d0 00007ffd`92113244     RPCRT4!NdrpClientCall2+0x33c
05 00000060`f85ff6f0 00007ffd`9509976c     RPCRT4!NdrClientCall2+0x24
06 00000060`f85ff730 00007ffd`950996d0     sechost!ScOpenServiceChannelHandle+0x4c
07 00000060`f85ff760 00007ffd`81551000     sechost!StartServiceCtrlDispatcherW+0x70
08 00000060`f85ff7a0 00007ffd`81550be0     winfsp_a64!FspServiceLoop+0xf0 [C:\Users\billziss\Projects\winfsp\src\dll\service.c @ 241] 
09 00000060`f85ff800 00007ffd`81528b54     winfsp_a64!FspServiceRunEx+0xa0 [C:\Users\billziss\Projects\winfsp\src\dll\service.c @ 92] 
0a 00000060`f85ff850 00007ffd`81528dbc     winfsp_a64!FspServiceRun+0x3c [C:\Users\billziss\Projects\winfsp\inc\winfsp\winfsp.h @ 1952] 
0b 00000060`f85ff880 00007ffd`94e91fa0     winfsp_a64!fsp_fuse_svcmain+0x34 [C:\Users\billziss\Projects\winfsp\src\dll\fuse\fuse_loop.c @ 42] 
0c 00000060`f85ff8a0 00007ffd`95a22bdc     KERNEL32!BaseThreadInitThunk+0x30
0d 00000060`f85ff8e0 00000000`00000000     ntdll!RtlUserThreadStart+0x3c

What is the ExceptionCode passed to RaiseException (first argument in register x0)?

0:009> r x0
x0=0000000000000005

The value 5 is familiar and is indeed the error code for ERROR_ACCESS_DENIED. So it looks that StartServiceCtrlDispatcherW is unable to convert the process into a service, because we are not running in the Windows service context; this is an expected and benign error. It reports this error as an exception, which then the Golang runtime converts into a badsignal2, which crashes in WriteFile.

Sure enough if I use the debugger to arrive at RtlDispatchException (which is the actual function that dispatches exceptions to exception handlers) and then arrange things in the debugger so that the Golang vectored exception handler is never called, StartServiceCtrlDispatcherW returns and the file system starts and runs just fine.

The fix for initExceptionHandler is to remove the line that calls AddVectoredExceptionHandler.

[hellvy-github]

Wow, nice investigation @billziss-gh :)
I haven't read it through because it might take some time for me. Just come to say thank you first.

[ncw]

@billziss-gh superb sleuthing and a great read - thank you for writing it up :-)

I will report these problems to Golang and possibly also provide patches for them (if my CLA with Google is still valid).

Great idea. The individual CLA is very easy to sign - all online. I made several contributions like that when I found bugs and made a CL to fix them!

If your debug was a crime movie, this would be the bit when the detective goes, "Ahhhh" even if the audience haven't figured it out quite yet :-)

And just what does register x1 which contains the lpBuffer contain?

0:008> d x1
00007ff7`5d3759c0  72 75 6e 74 69 6d 65 3a-20 73 69 67 6e 61 6c 20  runtime: signal 
00007ff7`5d3759d0  72 65 63 65 69 76 65 64-20 6f 6e 20 74 68 72 65  received on thre
00007ff7`5d3759e0  61 64 20 6e 6f 74 20 63-72 65 61 74 65 64 20 62  ad not created b
00007ff7`5d3759f0  79 20 47 6f 2e 0a 00 00-00 00 00 00 00 00 00 00  y Go............

[billziss-gh]

If your debug was a crime movie, this would be the bit when the detective goes, "Ahhhh" even if the audience haven't figured it out quite yet :-)

Indeed that was the moment that I realized that I was going to be able to figure this out :-)

[hellvy-github]

Hello, we're waiting Go project to check this issue right ? What issue number I should follow ?

[hellvy-github]

Hi, just come to check it out :)

[darthShadow]

golang/go#56082 is the currently open issue.