Giter Club home page Giter Club logo

Comments (17)

aviramha avatar aviramha commented on June 9, 2024

Hey @Ngalstyan4 - I suspect it wouldn't work because of relative path - mirrord always bypasses (doesn't handle) relative paths. Could you try this with a full path instead?

from mirrord.

Ngalstyan4 avatar Ngalstyan4 commented on June 9, 2024

Thanks for the prompt response!

I tried a full path by changing the Open line into the following:

db, err := bolt.Open("/home/ngalstyan/etcd/bbolt/hello.db", 777, nil)

I still see the same error. Note that hello.db is nonexistent when I run the program. Both with and without mirrord, the application successfully creates hello.db. But when running with mirrord, it fails with invalid argument, whether the path is relative or absolute.

from mirrord.

aviramha avatar aviramha commented on June 9, 2024

Got it! It is most likely we don't handle errors well (i.e given invalid argument instead of other error) - can you run the same with env RUST_LOG=mirrord=trace and provide it redacted?

from mirrord.

Ngalstyan4 avatar Ngalstyan4 commented on June 9, 2024

Here:

[link redacted, since it was reproduced below, with a simpler case]

Sorry, I tried disabling colors via TERM=dumb RUST_LOG_STYLE=never RUST_LOG=mirrord=trace, but it seems that did not succeed so the file has some non-ascii characters

from mirrord.

meowjesty avatar meowjesty commented on June 9, 2024

Managed to reproduce a failure with just:

  • sample.go
package main

import (
	"C"
	"os"
	"sync"
)

type Thing struct {
	rwlock sync.Mutex
	file   *os.File
}

func (thing *Thing) Close() {
	thing.rwlock.Lock()

	print("\n\n")

	defer thing.rwlock.Unlock()
}

func main() {
	file, err := os.OpenFile("/tmp/foo.txt", os.O_CREATE|os.O_RDWR, 777)

	if err != nil {
		thing := Thing{file: file}
		thing.Close()
	}
}
  • config.json
{
    "target": {
        "path": {
            "deployment": "sample-python-deployment"
        }
    },
    "agent": {
        "image": "meowjesty/mirrord-agent:latest",
        "image_pull_policy": "Always",
        "log_level": "warn,mirrord=trace",
        "ttl": 60
    },
    "feature": {
        "fs": {
            "mode": "write",
            "read_write": "/tmp.+"
        },
        "network": {
            "incoming": "mirror"
        }
    }
}

from mirrord.

meowjesty avatar meowjesty commented on June 9, 2024

The last logs I see are (with the minimal file sample above):

23-12-07T20:45:37.550583Z TRACE ThreadId(01) openat:open: mirrord_layer::file::ops: close time.busy=2.10ms time.idle=10.1µs fd=-100 path=Success("/tmp/foo.txt") open_options=OpenOptionsInternal { read: true, write: true, append: false, truncate: false, create: true, create_new: false } path=Success("/tmp/foo.txt") open_options=OpenOptionsInternal { read: true, write: true, append: false, truncate: false, create: true, create_new: false }
2023-12-07T20:45:37.550594Z TRACE ThreadId(01) openat: mirrord_layer::file::ops: close time.busy=2.13ms time.idle=27.5µs fd=-100 path=Success("/tmp/foo.txt") open_options=OpenOptionsInternal { read: true, write: true, append: false, truncate: false, create: true, create_new: false }
2023-12-07T20:45:37.550607Z TRACE ThreadId(01) mirrord_layer::go: c_abi_syscall6_handler: syscall=72 param1=5 param2=3 param3=0 param4=0 param5=0 param6=0
2023-12-07T20:45:37.550616Z TRACE ThreadId(01) mirrord_layer::go: c_abi_syscall6_handler: syscall=72 param1=5 param2=4 param3=34816 param4=0 param5=0 param6=0
2023-12-07T20:45:37.550621Z TRACE ThreadId(01) mirrord_layer::go: c_abi_syscall6_handler: syscall=291 param1=524288 param2=0 param3=0 param4=0 param5=0 param6=0
2023-12-07T20:45:37.550630Z TRACE ThreadId(01) mirrord_layer::go: c_abi_syscall6_handler: syscall=233 param1=6 param2=1 param3=7 param4=824634180956 param5=0 param6=0
2023-12-07T20:45:37.550640Z TRACE ThreadId(01) mirrord_layer::go: c_abi_syscall6_handler: syscall=233 param1=6 param2=1 param3=5 param4=824634181028 param5=0 param6=0
2023-12-07T20:45:37.550645Z TRACE ThreadId(01) mirrord_layer::go: c_abi_syscall6_handler: syscall=72 param1=5 param2=3 param3=0 param4=0 param5=0 param6=0
2023-12-07T20:45:37.550648Z TRACE ThreadId(01) mirrord_layer::go: c_abi_syscall6_handler: syscall=72 param1=5 param2=4 param3=32768 param4=0 param5=0 param6=0

Meanwhile, these are the logs from the bolt sample:

2023-12-07T20:49:43.885577Z TRACE ThreadId(01) openat: mirrord_layer::file::ops: close time.busy=1.63ms time.idle=19.3µs fd=-100 path=Success("/tmp/mirrord.db") open_options=OpenOptionsInternal { read: true, write: true, append: false, truncate: false, create: true, create_new: false }
2023-12-07T20:49:43.885588Z TRACE ThreadId(01) mirrord_layer::go: c_abi_syscall6_handler: syscall=72 param1=5 param2=3 param3=0 param4=0 param5=0 param6=0
2023-12-07T20:49:43.885595Z TRACE ThreadId(01) mirrord_layer::go: c_abi_syscall6_handler: syscall=72 param1=5 param2=4 param3=34816 param4=0 param5=0 param6=0
2023-12-07T20:49:43.885600Z TRACE ThreadId(01) mirrord_layer::go: c_abi_syscall6_handler: syscall=291 param1=524288 param2=0 param3=0 param4=0 param5=0 param6=0
2023-12-07T20:49:43.885608Z TRACE ThreadId(01) mirrord_layer::go: c_abi_syscall6_handler: syscall=233 param1=6 param2=1 param3=7 param4=824634180700 param5=0 param6=0
2023-12-07T20:49:43.885619Z TRACE ThreadId(01) mirrord_layer::go: c_abi_syscall6_handler: syscall=233 param1=6 param2=1 param3=5 param4=824634180772 param5=0 param6=0
2023-12-07T20:49:43.885624Z TRACE ThreadId(01) mirrord_layer::go: c_abi_syscall6_handler: syscall=72 param1=5 param2=3 param3=0 param4=0 param5=0 param6=0
2023-12-07T20:49:43.885629Z TRACE ThreadId(01) mirrord_layer::go: c_abi_syscall6_handler: syscall=72 param1=5 param2=4 param3=32768 param4=0 param5=0 param6=0
2023-12-07T20:49:43.885634Z TRACE ThreadId(01) mirrord_layer::go: c_abi_syscall6_handler: syscall=73 param1=5 param2=6 param3=0 param4=0 param5=0 param6=0
2023-12-07T20:49:43.885641Z TRACE ThreadId(01) mirrord_layer::go: c_abi_syscall6_handler: syscall=5 param1=5 param2=824634450392 param3=0 param4=0 param5=0 param6=0
2023-12-07T20:49:43.885648Z TRACE ThreadId(01) mirrord_layer::go: c_abi_syscall6_handler: syscall=18 param1=5 param2=824634466304 param3=16384 param4=0 param5=0 param6=0
2023-12-07T20:49:43.885654Z TRACE ThreadId(01) mirrord_layer::go: c_abi_syscall6_handler: syscall=73 param1=5 param2=8 param3=0 param4=0 param5=0 param6=0
2023-12-07T20:49:43.885658Z TRACE ThreadId(01) mirrord_layer::go: c_abi_syscall6_handler: syscall=3 param1=5 param2=0 param3=0 param4=0 param5=0 param6=0
2023-12-07T20:49:43.885687Z TRACE ThreadId(01) remote_close: mirrord_layer::file::ops: new fd=0
2023-12-07T20:49:43.885700Z TRACE ThreadId(01) remote_close:make_request_no_response: mirrord_layer::proxy_connection: new fd=0 request=CloseFileRequest { fd: 0 }
2023-12-07T20:49:43.885722Z TRACE ThreadId(01) remote_close:make_request_no_response: mirrord_layer::proxy_connection: return=Ok(2) fd=0 request=CloseFileRequest { fd: 0 }
2023-12-07T20:49:43.885735Z TRACE ThreadId(01) remote_close:make_request_no_response: mirrord_layer::proxy_connection: close time.busy=25.2µs time.idle=9.11µs fd=0 request=CloseFileRequest { fd: 0 }
2023-12-07T20:49:43.885749Z TRACE ThreadId(01) remote_close: mirrord_layer::file::ops: close time.busy=53.3µs time.idle=8.72µs fd=0
(0x4e5bd8,0xc0000b00c0)0x02023-12-07T20:49:44.936657Z TRACE ThreadId(02) mirrord_layer::go: c_abi_syscall6_handler: syscall=281 param1=6 param2=140736140055784 param3=128 param4=0 param5=0 param6=0
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x1b8 pc=0x493dc7]

goroutine 1 [running]:
go.etcd.io/bbolt.(*DB).Close(0x0)
        /home/meowjesty/go/pkg/mod/go.etcd.io/[email protected]/db.go:647 +0x47
main.main()
        /home/meowjesty/dev/metalbear/mirrord-samples/issue-2099/bolt_sample.go:45 +0xae

from mirrord.

Ngalstyan4 avatar Ngalstyan4 commented on June 9, 2024

Could you also log syscall results? I do not think they are in the logs above.
Could it be that c_abi_syscall6_handler does something strange with the result of some syscalls?

from mirrord.

meowjesty avatar meowjesty commented on June 9, 2024

Sorry for the late reply!

Kinda disregard my sample, it was produced amidst a ton of sneezing 🤧

Looks like the issue might be a missing hook, as boltdb calls this:

func Fdatasync(fd int) (err error) {
	_, _, e1 := Syscall(SYS_FDATASYNC, uintptr(fd), 0, 0)
	if e1 != 0 {
		err = errnoErr(e1)
	}
	return
}

when initializing the database from a file, which results in a bolt.Open: write /app/mirrord.db: bad file descriptor.

from mirrord.

meowjesty avatar meowjesty commented on June 9, 2024

After hooking fdatasync and pwrite64, the error is now file size too small from here:

func (db *DB) mmap(minsz int) (err error) {
	db.mmaplock.Lock()
	defer db.mmaplock.Unlock()

	info, err := db.file.Stat()
	if err != nil {
		return fmt.Errorf("mmap stat error: %s", err)
	} else if int(info.Size()) < db.pageSize*2 {
		return fmt.Errorf("file size too small")        <------
	}
    ...
}

Which is weird, because we successfully wrote a file that should be big, from the logs:

return=Ok(Ok(WriteFileResponse { written_amount: 16384 })) request=WriteLimitedFileRequest { remote_fd: 0, start_from: 0, write_bytes: 16384 }

from mirrord.

aviramha avatar aviramha commented on June 9, 2024

Maybe we don't handle stat @meowjesty ? Do you see it being called?

from mirrord.

meowjesty avatar meowjesty commented on June 9, 2024
c_abi_syscall6_handler: syscall=75 param1=5 param2=0 param3=0 param4=0 param5=0 param6=0 <-- fdatasync
c_abi_syscall6_handler: syscall=281 param1=6 param2=140736140088552 param3=128 param4=0 param5=0 param6=0 <-- epoll_pwait
c_abi_syscall6_handler: syscall=281 param1=6 param2=140736140088552 param3=128 param4=0 param5=0 param6=0
c_abi_syscall6_handler: syscall=281 param1=6 param2=140736140088552 param3=128 param4=0 param5=0 param6=0
c_abi_syscall6_handler: syscall=5 param1=5 param2=824635466408 param3=0 param4=0 param5=0 param6=0 <-- fstat
c_abi_syscall6_handler: syscall=281 param1=6 param2=140736140088552 param3=128 param4=0 param5=0 param6=0
c_abi_syscall6_handler: syscall=281 param1=6 param2=140736140088552 param3=128 param4=0 param5=0 param6=0
c_abi_syscall6_handler: syscall=281 param1=6 param2=140736140088552 param3=128 param4=0 param5=0 param6=0
c_abi_syscall6_handler: syscall=281 param1=6 param2=140736140088552 param3=128 param4=0 param5=0 param6=0
c_abi_syscall6_handler: syscall=281 param1=6 param2=140736140088552 param3=128 param4=0 param5=0 param6=0
c_abi_syscall6_handler: syscall=281 param1=6 param2=140736140088552 param3=128 param4=0 param5=0 param6=0
c_abi_syscall6_handler: syscall=73 param1=5 param2=8 param3=0 param4=0 param5=0 param6=0 <-- flock
c_abi_syscall6_handler: syscall=3 param1=5 param2=0 param3=0 param4=0 param5=0 param6=0 <-- close
c_abi_syscall6_handler: syscall=281 param1=6 param2=140736140088552 param3=128 param4=0 param5=0 param6=0

Yeah, looks like fstat is not hooked in go?

from mirrord.

meowjesty avatar meowjesty commented on June 9, 2024

Now I think it's pread64 failing:

c_abi_syscall6_handler: syscall=17 param1=5 param2=824634994152 param3=4096 param4=1024 param5=0 param6=0  <-- pread64
c_abi_syscall6_handler: syscall=17 param1=5 param2=824634994152 param3=4096 param4=2048 param5=0 param6=0
c_abi_syscall6_handler: syscall=17 param1=5 param2=824634994152 param3=4096 param4=4096 param5=0 param6=0
c_abi_syscall6_handler: syscall=17 param1=5 param2=824634994152 param3=4096 param4=8192 param5=0 param6=0

from mirrord.

meowjesty avatar meowjesty commented on June 9, 2024

And after hooking pread64, now it wants mmap:

c_abi_syscall6_handler: syscall=9 param1=0 param2=32768 param3=1 param4=1 param5=5 param6=0

from mirrord.

meowjesty avatar meowjesty commented on June 9, 2024

Alright, I'm reproducing this even when I bypass the file ops for the .db file that boltdb creates/manages.

It fails on mmap, even though the fd is not being handled by us, looks like our syscall handler for go might not be 100% working.

Just to clarify, you want to access this db file from your remote pod, or is it a local db file? @Ngalstyan4

from mirrord.

Ngalstyan4 avatar Ngalstyan4 commented on June 9, 2024

Remote - so no need for interception.
I think the fix should work for me. Will try out tomorrow. Thanks for looking into this and promptly fixing it!!

from mirrord.

aviramha avatar aviramha commented on June 9, 2024

@Ngalstyan4 remote won't work since file is probably also open by the remote pod itself

from mirrord.

eyalb181 avatar eyalb181 commented on June 9, 2024

Closing this for now - @Ngalstyan4 let us know if the fix didn't work and we'll reopen.

from mirrord.

Related Issues (20)

Recommend Projects

  • React photo React

    A declarative, efficient, and flexible JavaScript library for building user interfaces.

  • Vue.js photo Vue.js

    🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.

  • Typescript photo Typescript

    TypeScript is a superset of JavaScript that compiles to clean JavaScript output.

  • TensorFlow photo TensorFlow

    An Open Source Machine Learning Framework for Everyone

  • Django photo Django

    The Web framework for perfectionists with deadlines.

  • D3 photo D3

    Bring data to life with SVG, Canvas and HTML. 📊📈🎉

Recommend Topics

  • javascript

    JavaScript (JS) is a lightweight interpreted programming language with first-class functions.

  • web

    Some thing interesting about web. New door for the world.

  • server

    A server is a program made to process requests and deliver data to clients.

  • Machine learning

    Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.

  • Game

    Some thing interesting about game, make everyone happy.

Recommend Org

  • Facebook photo Facebook

    We are working to build community through open source technology. NB: members must have two-factor auth.

  • Microsoft photo Microsoft

    Open source projects and samples from Microsoft.

  • Google photo Google

    Google ❤️ Open Source for everyone.

  • D3 photo D3

    Data-Driven Documents codes.