Skip to content

transport type local panics on Illumos #598

Closed

Description

@jgmills

I'm running zrepl-0.5.0 on OI, an illumos distro. The daemon terminates with this error message:

panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x20 pc=0xaea33e]

goroutine 614 [running]:
github.com/zrepl/zrepl/rpc/grpcclientidentity.NewInterceptors.func1({0xf1e158, 0xc000631200}, {0xd514c0, 0xc000631230}, 0xc000032740, 0xc000524348)
	/dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/build/amd64/rpc/grpcclientidentity/authlistener_grpc_adaptor.go:121 +0x13e
github.com/zrepl/zrepl/replication/logic/pdu._Replication_ListFilesystems_Handler({0xdb30c0, 0xc00001a630}, {0xf1e158, 0xc000631200}, 0xc00052b7a0, 0xc000522000)
	/dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/build/amd64/replication/logic/pdu/pdu_grpc.pb.go:186 +0x16a
google.golang.org/grpc.(*Server).processUnaryRPC(0xc00016e700, {0xf2bc00, 0xc0000f2780}, 0xc00011c200, 0xc000522150, 0x1497c78, 0x0)
	/dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/zrepl-0.5.0/gopath/pkg/mod/google.golang.org/[email protected]/server.go:1217 +0xe28
google.golang.org/grpc.(*Server).handleStream(0xc00016e700, {0xf2bc00, 0xc0000f2780}, 0xc00011c200, 0x0)
	/dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/zrepl-0.5.0/gopath/pkg/mod/google.golang.org/[email protected]/server.go:1540 +0xcb3
google.golang.org/grpc.(*Server).serveStreams.func1.2(0xc000373b70, 0xc00016e700, {0xf2bc00, 0xc0000f2780}, 0xc00011c200)
	/dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/zrepl-0.5.0/gopath/pkg/mod/google.golang.org/[email protected]/server.go:878 +0xad
created by google.golang.org/grpc.(*Server).serveStreams.func1
	/dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/zrepl-0.5.0/gopath/pkg/mod/google.golang.org/[email protected]/server.go:876 +0x1ec

I was testing a replication config when this happened. Zrepl had not even created the intermediate filesystems when this happened. What causes this error? How do I prevent it?

Activity

  1. problame commented on May 7, 2022

    @problame
    Member

    So, the offending line is

    logger.WithField("peer_addr", p.Addr.String()).Debug("peer addr")

    I'm pretty sure logger != nil, but not so sure about p which is returned from gRPC's peer package.
    That code returns != nil on other platforms, but this seems like the kind of thing that could be broken on Illumos.

    Can you reproduce this?
    If so, please enable debug logs and provide them:

    https://zrepl.github.io/configuration/logging.html?highlight=logging

  2. jgmills commented on May 8, 2022

    @jgmills
    Author

    I will do the debug logging, but first I should report that I'm testing zrepl on a zpool that does not support feature flags of any sort. I created it this way:

    # zpool create -o version=15 dpool mirror ... ...

    Here's what "zpool status" says about it:

    # zpool status pool: dpool state: ONLINE status: The pool is formatted using a legacy on-disk format. The pool can still be used, but some features are unavailable. action: Upgrade the pool using 'zpool upgrade'. Once this is done, the pool will no longer be accessible on software that does not support feature flags. scan: none requested config: ...
    Nevertheless, zrepl should report the problem instead of dereferencing a null pointer.

  3. jgmills commented on May 14, 2022

    @jgmills
    Author

    Okay, this is part of the debugging log output. It's slightly reformatted to fit my screen, with empty lines between messages. I have the whole thing in raw format, if that helps.

    2022-05-14T14:38:05-05:00
    [INFO][backup_system][zfs.cmd][Uv38$ifuC$ifuC.3GZ8.vMC2.hsYJ.zcmI.a1u8.8MRF]:
    command exited without error systemtime_s="0.003" cmd="zfs get -Hp -o
    name,property,value,source encryption dpool/origin"
    total_time_s="0.008026785" usertime_s="0.002"
    
    2022-05-14T14:38:05-05:00
    [DEBG][backup_system][trace.data][Uv38$ifuC$ifuC.3GZ8.vMC2.hsYJ.zcmI.a1u8.8MRF]:
    finished span
    cli.(*Subcommand).run#0$active-side-job#0$active-side-job#0.active-side-job
    backup_system.invocation-1.replication.plan.endpoint.(*Sender).ListFilesystems.z
    +fs
    get -Hp -o name,property,value,source encryption dpool/origin
    duration_s="0.008391762"
    
    2022-05-14T14:38:05-05:00
    [DEBG][backup_system][trace.data][Uv38$ifuC$ifuC.3GZ8.vMC2.hsYJ.zcmI.a1u8]:
    finished span
    cli.(*Subcommand).run#0$active-side-job#0$active-side-job#0.active-side-job
    backup_system.invocation-1.replication.plan.endpoint.(*Sender).ListFilesystems
    duration_s="0.034690412"
    
    2022-05-14T14:38:05-05:00
    [DEBG][backup_system][trace.data][Uv38$ifuC$ifuC.3GZ8.vMC2.hsYJ.zcmI.xeyr]:
    begin span
    
    2022-05-14T14:38:05-05:00
    [DEBG][local_sink][rpc.ctrl][Uv38$wRT5$wRT5.wJxi]: request
    fullMethod="/Replication/ListFilesystems"
    
    panic: runtime error: invalid memory address or nil pointer dereference
    
    [signal SIGSEGV: segmentation violation code=0x1 addr=0x20 pc=0xaea33e]
    
  4. problame commented on May 15, 2022

    @problame
    Member

    These log messages don't provide enough context. I'd need the last 10 seconds or so.

    Also, please generate a coredump by running the zrepl daemon with GOTRACEBACK=crash.
    Learn more here: https://medium.com/a-journey-with-go/go-debugging-with-delve-core-dumps-384145b2e8d9

    (Don't post the coredump publicly, it contains sensitive information. Either use the dlv debugger to explore it yourself, or share it with me via e-mail)


    FYI, you can use three backticks to insert preformatted text. I edited your last message to make it look nice. Learn more at https://github.github.com/gfm/

  5. jgmills commented on May 15, 2022

    @jgmills
    Author

    Something peculiar happened when I prefixed the command with "env GOTRACEBACK=crash". It did dump core, as I expected, but the output ran off the screen. I tried it again, under "script" so I could capture all of the output. That time, it did not terminate with a core dump, but kept on going. The same thing happened when I tried it again without script. Both times I had to kill the daemon to terminate it. So, I have the full output from a previous run, without a corresponding core file, and the core file from the next run, without the output.

    By the way, illumos and OI do not have the "dlv" debugger. I can use "mdb" on the core file, but it's not particularly useful. I could send you the core file if I knew your e-mail address. Here is the full output from a previous run:

    2022-05-14T14:38:04-05:00 [INFO]: zrepl version=oi-20200504-2370-gd402c2588 go=go1.17.1 GOOS=illumos GOARCH=amd64 Compiler=gc
    2022-05-14T14:38:04-05:00 [INFO]: starting daemon
    2022-05-14T14:38:04-05:00 [INFO][_control][job][Uv38$Uv38]: starting job
    2022-05-14T14:38:04-05:00 [INFO][local_sink][job][Uv38$Uv38]: starting job
    2022-05-14T14:38:04-05:00 [DEBG][local_sink][trace.data][Uv38$wRT5$wRT5.wJxi]: begin span
    2022-05-14T14:38:04-05:00 [INFO][backup_system][job][Uv38$Uv38]: starting job
    2022-05-14T14:38:04-05:00 [DEBG][local_sink][rpc.ctrl][Uv38$wRT5$wRT5.wJxi]: accept authListener
    2022-05-14T14:38:04-05:00 [DEBG][backup_system][trace.data][Uv38$ifuC$ifuC.3GZ8]: begin span
    2022-05-14T14:38:04-05:00 [DEBG][local_sink][transport][Uv38$wRT5$wRT5.wJxi]: waiting for local client connect requests
    2022-05-14T14:38:04-05:00 [INFO][backup_system][job][Uv38$ifuC$ifuC.3GZ8]: wait for wakeups
    2022-05-14T14:38:04-05:00 [DEBG][backup_system][trace.data][Uv38$ifuC$ngdg$ngdg.gvXy]: begin span
    2022-05-14T14:38:04-05:00 [DEBG][backup_system][snapshot][Uv38$ifuC$ngdg$ngdg.gvXy]: start
    2022-05-14T14:38:04-05:00 [DEBG][backup_system][trace.data][Uv38$ifuC$ngdg$n1ey$n1ey.JFuD]: begin span
    2022-05-14T14:38:04-05:00 [DEBG][backup_system][zfs.cmd][Uv38$ifuC$ngdg$n1ey$n1ey.JFuD]: starting command cmd="zfs list -H -p -o name -r -t filesystem,volume"
    2022-05-14T14:38:04-05:00 [INFO][backup_system][zfs.cmd][Uv38$ifuC$ngdg$n1ey$n1ey.JFuD]: started command cmd="zfs list -H -p -o name -r -t filesystem,volume"
    2022-05-14T14:38:04-05:00 [DEBG][backup_system][zfs.cmd][Uv38$ifuC$ngdg$n1ey$n1ey.JFuD]: start waiting cmd="zfs list -H -p -o name -r -t filesystem,volume"
    2022-05-14T14:38:04-05:00 [INFO][backup_system][zfs.cmd][Uv38$ifuC$ngdg$n1ey$n1ey.JFuD]: command exited without error cmd="zfs list -H -p -o name -r -t filesystem,volume" total_time_s="0.01709973" systemtime_s="0.013" usertime_s="0.004"
    2022-05-14T14:38:04-05:00 [DEBG][backup_system][trace.data][Uv38$ifuC$ngdg$n1ey$n1ey.JFuD]: finished span cli.(*Subcommand).run#0$active-side-job#0$periodic#1$zfscmd#0$zfscmd#0.zfscmd zfs list -H -p -o name -r -t filesystem,volume duration_s="0.023752029"
    2022-05-14T14:38:04-05:00 [DEBG][backup_system][snapshot][Uv38$ifuC$ngdg$ngdg.gvXy]: examine filesystem state to find sync point
    2022-05-14T14:38:04-05:00 [DEBG][backup_system][trace.data][Uv38$ifuC$ngdg$NjxN$NjxN.5yMf]: begin span fs="dpool/origin"
    2022-05-14T14:38:04-05:00 [DEBG][backup_system][zfs.cmd][Uv38$ifuC$ngdg$NjxN$NjxN.5yMf]: starting command cmd="zfs list -H -p -o name,guid,createtxg,creation,userrefs -r -d 1 -t snapshot -s createtxg dpool/origin" fs="dpool/origin"
    2022-05-14T14:38:04-05:00 [INFO][backup_system][zfs.cmd][Uv38$ifuC$ngdg$NjxN$NjxN.5yMf]: started command fs="dpool/origin" cmd="zfs list -H -p -o name,guid,createtxg,creation,userrefs -r -d 1 -t snapshot -s createtxg dpool/origin"
    2022-05-14T14:38:04-05:00 [DEBG][backup_system][zfs.cmd][Uv38$ifuC$ngdg$NjxN$NjxN.5yMf]: start waiting fs="dpool/origin" cmd="zfs list -H -p -o name,guid,createtxg,creation,userrefs -r -d 1 -t snapshot -s createtxg dpool/origin"
    2022-05-14T14:38:04-05:00 [INFO][backup_system][zfs.cmd][Uv38$ifuC$ngdg$NjxN$NjxN.5yMf]: command exited without error cmd="zfs list -H -p -o name,guid,createtxg,creation,userrefs -r -d 1 -t snapshot -s createtxg dpool/origin" total_time_s="0.006155034" systemtime_s="0.004" usertime_s="0.002" fs="dpool/origin"
    2022-05-14T14:38:04-05:00 [DEBG][backup_system][trace.data][Uv38$ifuC$ngdg$NjxN$NjxN.5yMf]: finished span cli.(*Subcommand).run#0$active-side-job#0$periodic#1$zfscmd#0$zfscmd#0.zfscmd zfs list -H -p -o name,guid,createtxg,creation,userrefs -r -d 1 -t snapshot -s createtxg dpool/origin duration_s="0.008650416" fs="dpool/origin"
    2022-05-14T14:38:04-05:00 [DEBG][backup_system][snapshot][Uv38$ifuC$ngdg$ngdg.gvXy]: found latest snapshot fs="dpool/origin" creation="2022-04-25 18:54:28 -0500 CDT"
    2022-05-14T14:38:04-05:00 [DEBG][backup_system][snapshot][Uv38$ifuC$ngdg$ngdg.gvXy]: found optimal sync point for this filesystem fs="dpool/origin" syncPoint="2022-04-25 19:04:28 -0500 CDT"
    2022-05-14T14:38:04-05:00 [INFO][backup_system][snapshot][Uv38$ifuC$ngdg$ngdg.gvXy]: determined sync point syncPoint="2022-04-25 19:04:28 -0500 CDT"
    2022-05-14T14:38:04-05:00 [DEBG][backup_system][snapshot][Uv38$ifuC$ngdg$ngdg.gvXy]: state transition transition="SyncUp=>Planning"
    2022-05-14T14:38:04-05:00 [DEBG][backup_system][trace.data][Uv38$ifuC$ngdg$Vcvt$Vcvt.o/nn]: begin span
    2022-05-14T14:38:04-05:00 [DEBG][backup_system][zfs.cmd][Uv38$ifuC$ngdg$Vcvt$Vcvt.o/nn]: starting command cmd="zfs list -H -p -o name -r -t filesystem,volume"
    2022-05-14T14:38:04-05:00 [INFO][backup_system][zfs.cmd][Uv38$ifuC$ngdg$Vcvt$Vcvt.o/nn]: started command cmd="zfs list -H -p -o name -r -t filesystem,volume"
    2022-05-14T14:38:04-05:00 [DEBG][backup_system][zfs.cmd][Uv38$ifuC$ngdg$Vcvt$Vcvt.o/nn]: start waiting cmd="zfs list -H -p -o name -r -t filesystem,volume"
    2022-05-14T14:38:04-05:00 [INFO][backup_system][zfs.cmd][Uv38$ifuC$ngdg$Vcvt$Vcvt.o/nn]: command exited without error cmd="zfs list -H -p -o name -r -t filesystem,volume" total_time_s="0.015266064" systemtime_s="0.011" usertime_s="0.003"
    2022-05-14T14:38:04-05:00 [DEBG][backup_system][trace.data][Uv38$ifuC$ngdg$Vcvt$Vcvt.o/nn]: finished span cli.(*Subcommand).run#0$active-side-job#0$periodic#1$zfscmd#0$zfscmd#0.zfscmd zfs list -H -p -o name -r -t filesystem,volume duration_s="0.017689384"
    2022-05-14T14:38:04-05:00 [DEBG][backup_system][snapshot][Uv38$ifuC$ngdg$ngdg.gvXy]: state transition transition="Planning=>Snapshotting"
    2022-05-14T14:38:04-05:00 [DEBG][backup_system][snapshot][Uv38$ifuC$ngdg$ngdg.gvXy]: begin run job plan report="01 [Pending] [  ...] ~ [Callback]  snapshot" fs="dpool/origin" snap="zrepl_20220514_193804_000"
    2022-05-14T14:38:04-05:00 [INFO][backup_system][hook][Uv38$ifuC$ngdg$ngdg.gvXy]: run pre-edges in configuration order snap="zrepl_20220514_193804_000" fs="dpool/origin"
    2022-05-14T14:38:04-05:00 [INFO][backup_system][hook][Uv38$ifuC$ngdg$ngdg.gvXy]: running callback snap="zrepl_20220514_193804_000" fs="dpool/origin"
    2022-05-14T14:38:04-05:00 [DEBG][backup_system][snapshot][Uv38$ifuC$ngdg$ngdg.gvXy]: create snapshot fs="dpool/origin" snap="zrepl_20220514_193804_000"
    2022-05-14T14:38:04-05:00 [DEBG][backup_system][trace.data][Uv38$ifuC$ngdg$ngdg.gvXy.btTn]: begin span fs="dpool/origin" snap="zrepl_20220514_193804_000"
    2022-05-14T14:38:04-05:00 [DEBG][backup_system][zfs.cmd][Uv38$ifuC$ngdg$ngdg.gvXy.btTn]: starting command snap="zrepl_20220514_193804_000" fs="dpool/origin" cmd="zfs snapshot dpool/origin@zrepl_20220514_193804_000"
    2022-05-14T14:38:04-05:00 [INFO][backup_system][zfs.cmd][Uv38$ifuC$ngdg$ngdg.gvXy.btTn]: started command snap="zrepl_20220514_193804_000" fs="dpool/origin" cmd="zfs snapshot dpool/origin@zrepl_20220514_193804_000"
    2022-05-14T14:38:04-05:00 [DEBG][backup_system][zfs.cmd][Uv38$ifuC$ngdg$ngdg.gvXy.btTn]: start waiting snap="zrepl_20220514_193804_000" fs="dpool/origin" cmd="zfs snapshot dpool/origin@zrepl_20220514_193804_000"
    2022-05-14T14:38:05-05:00 [INFO][backup_system][zfs.cmd][Uv38$ifuC$ngdg$ngdg.gvXy.btTn]: command exited without error cmd="zfs snapshot dpool/origin@zrepl_20220514_193804_000" total_time_s="0.831380062" usertime_s="0.002" systemtime_s="0.004" snap="zrepl_20220514_193804_000" fs="dpool/origin"
    2022-05-14T14:38:05-05:00 [DEBG][backup_system][trace.data][Uv38$ifuC$ngdg$ngdg.gvXy.btTn]: finished span cli.(*Subcommand).run#0$active-side-job#0$periodic#1$periodic#1.daemon/snapper.(*Snapper).Run.zfs snapshot dpool/origin@zrepl_20220514_193804_000 fs="dpool/origin" snap="zrepl_20220514_193804_000" duration_s="0.833977746"
    2022-05-14T14:38:05-05:00 [INFO][backup_system][hook][Uv38$ifuC$ngdg$ngdg.gvXy]: run post-edges for successful pre-edges in reverse configuration order fs="dpool/origin" snap="zrepl_20220514_193804_000"
    2022-05-14T14:38:05-05:00 [INFO][backup_system][snapshot][Uv38$ifuC$ngdg$ngdg.gvXy]: end run job plan successful snap="zrepl_20220514_193804_000" fs="dpool/origin" report="01 [Ok] [834ms] ~ [Callback]  snapshot"
    2022-05-14T14:38:05-05:00 [DEBG][backup_system][snapshot][Uv38$ifuC$ngdg$ngdg.gvXy]: state transition transition="Snapshotting=>Waiting"
    2022-05-14T14:38:05-05:00 [DEBG][backup_system][snapshot][Uv38$ifuC$ngdg$ngdg.gvXy]: enter wait-state after error duration="10m0s" sleep_until="2022-05-14 14:48:04.209505281 -0500 CDT m=+600.055765460"
    2022-05-14T14:38:05-05:00 [DEBG][backup_system][trace.data][Uv38$ifuC$ifuC.3GZ8.vMC2]: begin span
    2022-05-14T14:38:05-05:00 [DEBG][backup_system][trace.data][Uv38$ifuC$ifuC.3GZ8.vMC2.hsYJ]: begin span
    2022-05-14T14:38:05-05:00 [DEBG][local_sink][transport][Uv38$wRT5$wRT5.wJxi]: got connect request client_identity="local_backup"
    2022-05-14T14:38:05-05:00 [DEBG][local_sink][transport][Uv38$wRT5$wRT5.wJxi]: creating socketpair
    2022-05-14T14:38:05-05:00 [INFO][backup_system][job][Uv38$ifuC$ifuC.3GZ8.vMC2.hsYJ]: start replication
    2022-05-14T14:38:05-05:00 [DEBG][backup_system][repl][Uv38$ifuC$ifuC.3GZ8.vMC2.hsYJ]: begin run
    2022-05-14T14:38:05-05:00 [DEBG][backup_system][repl][Uv38$ifuC$ifuC.3GZ8.vMC2.hsYJ]: start attempt attempt_number="0"
    2022-05-14T14:38:05-05:00 [DEBG][local_sink][transport][Uv38$wRT5$wRT5.wJxi]: responding with left side of socketpair
    2022-05-14T14:38:05-05:00 [DEBG][local_sink][transport][Uv38$wRT5$wRT5.wJxi]: responding to client request res.err="<nil>" res.conn="&{{0xc0003b0080}}"
    2022-05-14T14:38:05-05:00 [DEBG][local_sink][transport][Uv38$wRT5$wRT5.wJxi]: panic on send to client callback, likely a legitimate client-side timeout recover_err="<nil>"
    2022-05-14T14:38:05-05:00 [DEBG][backup_system][trace.data][Uv38$ifuC$ifuC.3GZ8.vMC2.hsYJ.zcmI]: begin span
    2022-05-14T14:38:05-05:00 [DEBG][backup_system][rpc][Uv38$ifuC$ifuC.3GZ8.vMC2]: grpc state change grpc_state="CONNECTING"
    2022-05-14T14:38:05-05:00 [DEBG][local_sink][transport][Uv38$wRT5$wRT5.wJxi]: waiting for local client connect requests
    2022-05-14T14:38:05-05:00 [INFO][backup_system][repl][Uv38$ifuC$ifuC.3GZ8.vMC2.hsYJ.zcmI]: start planning
    2022-05-14T14:38:05-05:00 [DEBG][backup_system][trace.data][Uv38$ifuC$ifuC.3GZ8.vMC2.hsYJ.zcmI.a1u8]: begin span
    2022-05-14T14:38:05-05:00 [DEBG][backup_system][rpc.ctrl][Uv38$ifuC$ifuC.3GZ8.vMC2]: ClientHandshake url="doesn't matter done by dialer" connType="*net.UnixConn"
    2022-05-14T14:38:05-05:00 [DEBG][backup_system][trace.data][Uv38$ifuC$+u0a$+u0a.ICAu]: begin span
    2022-05-14T14:38:05-05:00 [DEBG][backup_system][zfs.cmd][Uv38$ifuC$+u0a$+u0a.ICAu]: starting command cmd="zfs list -H -p -o name -r -t filesystem,volume"
    2022-05-14T14:38:05-05:00 [DEBG][local_sink][rpc.ctrl][Uv38$wRT5$wRT5.wJxi]: accept authListener
    2022-05-14T14:38:05-05:00 [DEBG][local_sink][rpc.ctrl][Uv38$wRT5$wRT5.wJxi]: ServerHandshake connType="*transport.AuthConn"
    2022-05-14T14:38:05-05:00 [DEBG][backup_system][rpc][Uv38$ifuC$ifuC.3GZ8.vMC2]: grpc state change grpc_state="READY"
    2022-05-14T14:38:05-05:00 [INFO][backup_system][zfs.cmd][Uv38$ifuC$+u0a$+u0a.ICAu]: started command cmd="zfs list -H -p -o name -r -t filesystem,volume"
    2022-05-14T14:38:05-05:00 [DEBG][backup_system][zfs.cmd][Uv38$ifuC$+u0a$+u0a.ICAu]: start waiting cmd="zfs list -H -p -o name -r -t filesystem,volume"
    2022-05-14T14:38:05-05:00 [INFO][backup_system][zfs.cmd][Uv38$ifuC$+u0a$+u0a.ICAu]: command exited without error usertime_s="0.004" cmd="zfs list -H -p -o name -r -t filesystem,volume" total_time_s="0.015324252" systemtime_s="0.012"
    2022-05-14T14:38:05-05:00 [DEBG][backup_system][trace.data][Uv38$ifuC$+u0a$+u0a.ICAu]: finished span cli.(*Subcommand).run#0$active-side-job#0$zfscmd#0$zfscmd#0.zfscmd zfs list -H -p -o name -r -t filesystem,volume duration_s="0.018862231"
    2022-05-14T14:38:05-05:00 [DEBG][backup_system][trace.data][Uv38$ifuC$ifuC.3GZ8.vMC2.hsYJ.zcmI.a1u8.JJYp]: begin span
    2022-05-14T14:38:05-05:00 [DEBG][backup_system][zfs.cmd][Uv38$ifuC$ifuC.3GZ8.vMC2.hsYJ.zcmI.a1u8.JJYp]: starting command cmd="zfs load-key"
    2022-05-14T14:38:05-05:00 [INFO][backup_system][zfs.cmd][Uv38$ifuC$ifuC.3GZ8.vMC2.hsYJ.zcmI.a1u8.JJYp]: started command cmd="zfs load-key"
    2022-05-14T14:38:05-05:00 [DEBG][backup_system][zfs.cmd][Uv38$ifuC$ifuC.3GZ8.vMC2.hsYJ.zcmI.a1u8.JJYp]: start waiting cmd="zfs load-key"
    2022-05-14T14:38:05-05:00 [INFO][backup_system][zfs.cmd][Uv38$ifuC$ifuC.3GZ8.vMC2.hsYJ.zcmI.a1u8.JJYp]: command exited with error usertime_s="0.001" cmd="zfs load-key" err="exit status 2" systemtime_s="0.002" total_time_s="0.006206665"
    2022-05-14T14:38:05-05:00 [DEBG][backup_system][trace.data][Uv38$ifuC$ifuC.3GZ8.vMC2.hsYJ.zcmI.a1u8.JJYp]: finished span cli.(*Subcommand).run#0$active-side-job#0$active-side-job#0.active-side-job backup_system.invocation-1.replication.plan.endpoint.(*Sender).ListFilesystems.zfs load-key duration_s="0.006613346"
    2022-05-14T14:38:05-05:00 [DEBG][backup_system][trace.data][Uv38$ifuC$ifuC.3GZ8.vMC2.hsYJ.zcmI.a1u8.8MRF]: begin span
    2022-05-14T14:38:05-05:00 [DEBG][backup_system][zfs.cmd][Uv38$ifuC$ifuC.3GZ8.vMC2.hsYJ.zcmI.a1u8.8MRF]: starting command cmd="zfs get -Hp -o name,property,value,source encryption dpool/origin"
    2022-05-14T14:38:05-05:00 [INFO][backup_system][zfs.cmd][Uv38$ifuC$ifuC.3GZ8.vMC2.hsYJ.zcmI.a1u8.8MRF]: started command cmd="zfs get -Hp -o name,property,value,source encryption dpool/origin"
    2022-05-14T14:38:05-05:00 [DEBG][backup_system][zfs.cmd][Uv38$ifuC$ifuC.3GZ8.vMC2.hsYJ.zcmI.a1u8.8MRF]: start waiting cmd="zfs get -Hp -o name,property,value,source encryption dpool/origin"
    2022-05-14T14:38:05-05:00 [INFO][backup_system][zfs.cmd][Uv38$ifuC$ifuC.3GZ8.vMC2.hsYJ.zcmI.a1u8.8MRF]: command exited without error systemtime_s="0.003" cmd="zfs get -Hp -o name,property,value,source encryption dpool/origin" total_time_s="0.008026785" usertime_s="0.002"
    2022-05-14T14:38:05-05:00 [DEBG][backup_system][trace.data][Uv38$ifuC$ifuC.3GZ8.vMC2.hsYJ.zcmI.a1u8.8MRF]: finished span cli.(*Subcommand).run#0$active-side-job#0$active-side-job#0.active-side-job backup_system.invocation-1.replication.plan.endpoint.(*Sender).ListFilesystems.zfs get -Hp -o name,property,value,source encryption dpool/origin duration_s="0.008391762"
    2022-05-14T14:38:05-05:00 [DEBG][backup_system][trace.data][Uv38$ifuC$ifuC.3GZ8.vMC2.hsYJ.zcmI.a1u8]: finished span cli.(*Subcommand).run#0$active-side-job#0$active-side-job#0.active-side-job backup_system.invocation-1.replication.plan.endpoint.(*Sender).ListFilesystems duration_s="0.034690412"
    2022-05-14T14:38:05-05:00 [DEBG][backup_system][trace.data][Uv38$ifuC$ifuC.3GZ8.vMC2.hsYJ.zcmI.xeyr]: begin span
    2022-05-14T14:38:05-05:00 [DEBG][local_sink][rpc.ctrl][Uv38$wRT5$wRT5.wJxi]: request fullMethod="/Replication/ListFilesystems"
    panic: runtime error: invalid memory address or nil pointer dereference
    [signal SIGSEGV: segmentation violation code=0x1 addr=0x20 pc=0xaea33e]
    
    goroutine 187 [running]:
    github.com/zrepl/zrepl/rpc/grpcclientidentity.NewInterceptors.func1({0xf1e158, 0xc0002549f0}, {0xd514c0, 0xc000254a20}, 0xc00019a5c0, 0xc000260120)
            /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/build/amd64/rpc/grpcclientidentity/authlistener_grpc_adaptor.go:121 +0x13e
    github.com/zrepl/zrepl/replication/logic/pdu._Replication_ListFilesystems_Handler({0xdb30c0, 0xc0000f4510}, {0xf1e158, 0xc0002549f0}, 0xc00024ca20, 0xc00029e510)
    
  6. problame commented on Jun 19, 2022

    @problame
    Member

    My conclusion from this output is still the same as above.

    We're using socketpair to implement the local transport type. Maybe gRPC is a little special about it on Illumos?

    You can send the coredumps to me, using the e-mail address on my website, or the one that shows in my GitHub profile.

  7. jgmills commented on Jun 20, 2022

    @jgmills
    Author

    I will try sending the core file by e-mail, but I may run up against the size limit enforced by my e-mail service. I'll let you know what happens. In the meantime, here is an mdb session against the core file:

    core:		ELF 64-bit LSB core file AMD64 Version 1, from 'zrepl'
    <root@tyan># mdb core
    Loading modules: [ libc.so.1 ld.so.1 ]
    > ::status
    debugging core file of zrepl (64-bit) from tyan
    file: /usr/bin/zrepl
    initial argv: zrepl daemon
    threading model: native threads
    status: process terminated by SIGABRT (Abort), pid=1829 uid=0 code=-1
    > ::stack
    libc.so.1`_lwp_kill+0xa()
    libc.so.1`raise+0x1e(6)
    runtime.asmsysvicall6+0x5a()
    runtime.dieFromSignal+0x51()
    runtime.sigfwdgo+0x18b()
    runtime.sigtrampgo+0x34()
    runtime.sigtramp+0x10d()
    0()
    0x7fff84ffff48()
    > ^D
    <root@tyan># ll core
    -rw-------   1 root     root     73013448 May 15 10:08 core
    

    As you can see, it's not very useful for this core dump.

  8. jgmills commented on Jun 24, 2022

    @jgmills
    Author

    Yes, I was unable to send the core file to you through e-mail. My e-mail service did block it because of its size. Is there some other way I could get the core file to you?

  9. problame commented on Jun 25, 2022

    @problame
    Member

    Sent an upload link to you via email.

  10. jgmills commented on Jun 25, 2022

    @jgmills
    Author

    Thanks. I uploaded zrepl.core to that location.

  11. problame commented on Jun 27, 2022

    @problame
    Member

    Would you please upload the zrepl binary to that location as well?

  12. jgmills commented on Jun 27, 2022

    @jgmills
    Author

    I just uploaded this file:

    -r-xr-xr-x   1 mills    staff    23890859 Apr 19 12:35 /tmp/zrepl.bin
    
  13. problame commented on Jun 27, 2022

    @problame
    Member

    Quick glimpse at the core dump confirms that p is nil:

    cs@cslap:[~/zrepl/zrepl]: dlv core zrepl.bin zrepl.core
    Type 'help' for list of commands.
    (dlv) grs
      Goroutine 1 - User: /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/build/amd64/daemon/daemon.go:118 github.com/zrepl/zrepl/daemon.Run (0xb5f445) [select 459571h23m53.868196416s]
      Goroutine 2 - User: /usr/lib/golang/1.17/src/runtime/proc.go:367 runtime.gopark (0x43f5c5) [force gc (idle) 459571h23m53.868232091s]
      Goroutine 3 - User: /usr/lib/golang/1.17/src/runtime/proc.go:367 runtime.gopark (0x43f5c5) [GC sweep wait]
      Goroutine 4 - User: /usr/lib/golang/1.17/src/runtime/proc.go:367 runtime.gopark (0x43f5c5) [sleep]
      Goroutine 5 - User: /usr/lib/golang/1.17/src/runtime/proc.go:367 runtime.gopark (0x43f5c5) [finalizer wait]
      Goroutine 6 - User: /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/build/amd64/daemon/logging/trace/trace_chrometrace.go:146 github.com/zrepl/zrepl/daemon/logging/trace.init.2.func1 (0x89e775) [select]
      Goroutine 10 - User: /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/build/amd64/daemon/control.go:174 github.com/zrepl/zrepl/daemon.(*controlJob).Run (0xb5cd2d) [select 459571h23m53.868306741s]
      Goroutine 19 - User: /usr/lib/golang/1.17/src/runtime/proc.go:367 runtime.gopark (0x43f5c5) [GC worker (idle)]
      Goroutine 20 - User: /usr/lib/golang/1.17/src/runtime/proc.go:367 runtime.gopark (0x43f5c5) [GC worker (idle)]
      Goroutine 21 - User: /usr/lib/golang/1.17/src/runtime/proc.go:367 runtime.gopark (0x43f5c5) [GC worker (idle)]
      Goroutine 32 - User: /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/build/amd64/rpc/rpc_client.go:60 github.com/zrepl/zrepl/rpc.NewClient.func1.1 (0xaf20f8) [chan receive 459571h23m53.868361619s]
      Goroutine 33 - User: /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/zrepl-0.5.0/gopath/pkg/mod/google.golang.org/[email protected]/internal/transport/transport.go:321 google.golang.org/grpc/internal/transport.(*Stream).waitOnHeader (0x9a928b) [select]
      Goroutine 35 - User: /usr/lib/golang/1.17/src/runtime/proc.go:367 runtime.gopark (0x43f5c5) [GC worker (idle)]
      Goroutine 50 - User: /usr/lib/golang/1.17/src/runtime/proc.go:367 runtime.gopark (0x43f5c5) [select 459571h23m53.868400793s]
      Goroutine 51 - User: /usr/lib/golang/1.17/src/runtime/sigqueue.go:169 os/signal.signal_recv (0x46ff4b)
      Goroutine 52 - User: /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/build/amd64/daemon/daemon.go:38 github.com/zrepl/zrepl/daemon.Run.func1 (0xb5f7b4) [chan receive 459571h23m53.868424241s]
      Goroutine 56 - User: /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/build/amd64/rpc/transportmux/transportmux.go:116 github.com/zrepl/zrepl/rpc/transportmux.Demux.func1 (0xaf0965) [chan receive 459571h23m53.868445902s]
      Goroutine 57 - User: /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/build/amd64/transport/local/serve_local.go:134 github.com/zrepl/zrepl/transport/local.(*LocalListener).Accept (0xaf64d4) [select]
      Goroutine 58 - User: /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/build/amd64/rpc/netadaptor/authlistener_netlistener_adaptor.go:79 github.com/zrepl/zrepl/rpc/netadaptor.Listener.Accept (0xaeae98) [chan receive]
      Goroutine 59 - User: /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/build/amd64/rpc/dataconn/dataconn_server.go:104 github.com/zrepl/zrepl/rpc/dataconn.(*Server).Serve (0xae7a7f) [chan receive 459571h23m53.868483105s]
      Goroutine 60 - User: /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/build/amd64/rpc/dataconn/dataconn_server.go:80 github.com/zrepl/zrepl/rpc/dataconn.(*Server).Serve.func1 (0xae7e16) [chan receive 459571h23m53.868497295s]
      Goroutine 61 - User: /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/build/amd64/rpc/transportmux/transportmux.go:51 github.com/zrepl/zrepl/rpc/transportmux.(*demuxListener).Accept (0xaef389) [select 459571h23m53.868508494s]
      Goroutine 64 - User: /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/build/amd64/rpc/rpc_server.go:63 github.com/zrepl/zrepl/rpc.NewServer.func1.2 (0xaf476c) [chan receive 459571h23m53.868523168s]
      Goroutine 65 - User: /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/build/amd64/rpc/transportmux/transportmux.go:51 github.com/zrepl/zrepl/rpc/transportmux.(*demuxListener).Accept (0xaef389) [select]
      Goroutine 68 - User: /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/build/amd64/rpc/rpc_server.go:117 github.com/zrepl/zrepl/rpc.(*Server).Serve (0xaf4d0e) [select 459571h23m53.868545994s]
      Goroutine 74 - User: /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/build/amd64/replication/driver/replication_driver.go:300 github.com/zrepl/zrepl/replication/driver.Do.func2 (0xac8c85) [chan receive 459571h23m53.868560693s]
      Goroutine 75 - User: /usr/lib/golang/1.17/src/runtime/sema.go:56 sync.runtime_Semacquire (0x46f745) [semacquire 459571h23m53.868572285s]
      Goroutine 82 - User: /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/build/amd64/daemon/pprof.go:45 github.com/zrepl/zrepl/daemon.(*pprofServer).controlLoop (0xb60b66) [select 459571h23m53.868586515s]
      Goroutine 83 - User: /usr/lib/golang/1.17/src/runtime/netpoll.go:229 internal/poll.runtime_pollWait (0x46dd45) [IO wait 459571h23m53.868597824s]
      Goroutine 104 - User: /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/build/amd64/daemon/snapper/snapper.go:376 github.com/zrepl/zrepl/daemon/snapper.wait (0xa9ed26) [select 459571h23m53.868613393s]
      Goroutine 126 - User: /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/zrepl-0.5.0/gopath/pkg/mod/google.golang.org/[email protected]/balancer_conn_wrappers.go:69 google.golang.org/grpc.(*ccBalancerWrapper).watcher (0x9da425) [select]
      Goroutine 127 - User: /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/zrepl-0.5.0/gopath/pkg/mod/google.golang.org/[email protected]/clientconn.go:1213 google.golang.org/grpc.(*addrConn).resetTransport (0x9e3079) [chan receive]
      Goroutine 128 - User: /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/zrepl-0.5.0/gopath/pkg/mod/google.golang.org/[email protected]/clientconn.go:529 google.golang.org/grpc.(*ClientConn).WaitForStateChange (0x9def66) [select]
      Goroutine 129 - User: /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/build/amd64/daemon/job/active.go:472 github.com/zrepl/zrepl/daemon/job.(*ActiveSide).do.func1 (0xb0cb6c) [select 459571h23m53.868663747s]
      Goroutine 188 - User: /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/zrepl-0.5.0/gopath/pkg/mod/google.golang.org/[email protected]/internal/transport/controlbuf.go:395 google.golang.org/grpc/internal/transport.(*controlBuffer).get (0x9855c5) [select]
      Goroutine 199 - User: /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/zrepl-0.5.0/gopath/pkg/mod/google.golang.org/[email protected]/internal/transport/http2_client.go:1404 google.golang.org/grpc/internal/transport.(*http2Client).keepalive (0x999109) [select]
      Goroutine 200 - User: /usr/lib/golang/1.17/src/runtime/netpoll.go:229 internal/poll.runtime_pollWait (0x46dd45) [IO wait]
      Goroutine 203 - User: /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/zrepl-0.5.0/gopath/pkg/mod/google.golang.org/[email protected]/internal/transport/controlbuf.go:395 google.golang.org/grpc/internal/transport.(*controlBuffer).get (0x9855c5) [select]
      Goroutine 204 - User: /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/zrepl-0.5.0/gopath/pkg/mod/google.golang.org/[email protected]/internal/transport/http2_server.go:979 google.golang.org/grpc/internal/transport.(*http2Server).keepalive (0x9a1993) [select]
      Goroutine 205 - User: /usr/lib/golang/1.17/src/runtime/netpoll.go:229 internal/poll.runtime_pollWait (0x46dd45) [IO wait]
      Goroutine 299 - User: /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/build/amd64/rpc/grpcclientidentity/authlistener_grpc_adaptor.go:121 github.com/zrepl/zrepl/rpc/grpcclientidentity.NewInterceptors.func1 (0xaea33e)
    [41 goroutines]
    (dlv) gr 299
    Switched from 0 to 299 (thread 0)
    (dlv) bt
     0  0x0000000000472680 in runtime.systemstack_switch
        at /usr/lib/golang/1.17/src/runtime/asm_amd64.s:350
     1  0x00000000004389f5 in runtime.sysvicall1Err
        at /usr/lib/golang/1.17/src/runtime/os_solaris.go:96
     2  0x0000000000454d11 in runtime.sysvicall1
        at /usr/lib/golang/1.17/src/runtime/os_solaris.go:66
     3  0x0000000000454d11 in runtime.raise
        at /usr/lib/golang/1.17/src/runtime/os3_solaris.go:459
     4  0x0000000000454d11 in runtime.dieFromSignal
        at /usr/lib/golang/1.17/src/runtime/signal_unix.go:769
     5  0x000000000043c9f9 in runtime.crash
        at /usr/lib/golang/1.17/src/runtime/signal_unix.go:861
     6  0x000000000043c9f9 in runtime.fatalpanic
        at /usr/lib/golang/1.17/src/runtime/panic.go:1298
     7  0x000000000043c105 in runtime.gopanic
        at /usr/lib/golang/1.17/src/runtime/panic.go:1147
     8  0x0000000000454bae in runtime.panicmem
        at /usr/lib/golang/1.17/src/runtime/panic.go:221
     9  0x0000000000454bae in runtime.sigpanic
        at /usr/lib/golang/1.17/src/runtime/signal_unix.go:735
    10  0x0000000000aea33e in github.com/zrepl/zrepl/rpc/grpcclientidentity.NewInterceptors.func1
        at /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/build/amd64/rpc/grpcclientidentity/authlistener_grpc_adaptor.go:121
    11  0x0000000000a0b8aa in github.com/zrepl/zrepl/replication/logic/pdu._Replication_ListFilesystems_Handler
        at /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/build/amd64/replication/logic/pdu/pdu_grpc.pb.go:186
    12  0x00000000009f15e8 in google.golang.org/grpc.(*Server).processUnaryRPC
        at /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/zrepl-0.5.0/gopath/pkg/mod/google.golang.org/[email protected]/server.go:1217
    13  0x00000000009f5c73 in google.golang.org/grpc.(*Server).handleStream
        at /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/zrepl-0.5.0/gopath/pkg/mod/google.golang.org/[email protected]/server.go:1540
    14  0x00000000009ef02d in google.golang.org/grpc.(*Server).serveStreams.func1.2
        at /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/zrepl-0.5.0/gopath/pkg/mod/google.golang.org/[email protected]/server.go:878
    15  0x0000000000474881 in runtime.goexit
        at /usr/lib/golang/1.17/src/runtime/asm_amd64.s:1581
    (dlv) frame 10
    Stopped at: 0x0
    =>   1:	no source available
    Frame 10: /dpool/export/home/mills/Downloads/code/oi-userland-gh/components/sysutils/zrepl/build/amd64/rpc/grpcclientidentity/authlistener_grpc_adaptor.go:121 (PC: aea33e)
    (dlv) info locals
    Command failed: command not available
    (dlv) locals
    logger = github.com/zrepl/zrepl/logger.Logger(*github.com/zrepl/zrepl/logger.loggerImpl) 0xbeef000000000208
    p = *(unreadable read out of bounds)
    (dlv) p *p
    Command failed: nil pointer dereference
    
    

    So, why did

    p, ok := peer.FromContext(ctx) return nil, ok?

    Let's inspect the local ctx, which for some reason doesn't show up in dlv's locals output, but is still accessible:

    (dlv) p ctx
    context.Context(*context.valueCtx) *{
    	Context: context.Context(*context.valueCtx) *{
    		Context: context.Context(*context.valueCtx) ...,
    		key: (unreadable could not resolve interface type),
    		val: interface {}(google.golang.org/grpc/metadata.MD) *(*interface {})(0xc0004eb850),},
    	key: (unreadable could not resolve interface type),
    	val: interface {}(*google.golang.org/grpc/internal/transport.Stream) *{
    		id: 1,
    		st: google.golang.org/grpc/internal/transport.ServerTransport(*google.golang.org/grpc/internal/transport.http2Server) ...,
    		ct: *google.golang.org/grpc/internal/transport.http2Client nil,
    		ctx: context.Context(*context.valueCtx) ...,
    		cancel: context.WithCancel.func1,
    		done: chan struct {} {},
    		ctxDone: <-chan struct {} {
    			qcount: 0,
    			dataqsiz: 0,
    			buf: *[0]struct struct {} [],
    			elemsize: 0,
    			closed: 0,
    			elemtype: *runtime._type {size: 0, ptrdata: 0, hash: 670477339, tflag: tflagExtraStar|tflagRegularMemory (10), align: 1, fieldAlign: 1, kind: 25, equal: runtime.memequal0, gcdata: *0, str: 42520, ptrToThis: 0},
    			sendx: 0,
    			recvx: 0,
    			recvq: waitq<struct {}> {
    				first: *sudog<struct {}> nil,
    				last: *sudog<struct {}> nil,},
    			sendq: waitq<struct {}> {
    				first: *sudog<struct {}> nil,
    				last: *sudog<struct {}> nil,},
    			lock: runtime.mutex {
    				lockRankStruct: runtime.lockRankStruct {},
    				key: 0,},},
    		method: "/Replication/ListFilesystems",
    		recvCompress: "",
    		sendCompress: "",
    		buf: *(*"google.golang.org/grpc/internal/transport.recvBuffer")(0xc00037eb80),
    		trReader: io.Reader(*google.golang.org/grpc/internal/transport.transportReader) ...,
    		fc: *(*"google.golang.org/grpc/internal/transport.inFlow")(0xc00064c240),
    		wq: *(*"google.golang.org/grpc/internal/transport.writeQuota")(0xc00038a9e0),
    		requestRead: google.golang.org/grpc/internal/transport.(*http2Server).operateHeaders.func4,
    		headerChan: chan struct {} {},
    		headerChanClosed: 0,
    		headerValid: false,
    		hdrMu: (*sync.Mutex)(0xc0000aa4b8),
    		header: google.golang.org/grpc/metadata.MD nil,
    		trailer: google.golang.org/grpc/metadata.MD nil,
    		noHeaders: false,
    		headerSent: 0,
    		state: streamReadDone (2),
    		status: *google.golang.org/grpc/internal/status.Status nil,
    		bytesReceived: 0,
    		unprocessed: 0,
    		contentSubtype: "",},}
    (dlv) p ctx.val.ctx
    context.Context(*context.valueCtx) *{
    	Context: context.Context(*context.valueCtx) *{
    		Context: context.Context(*context.cancelCtx) ...,
    		key: (unreadable could not resolve interface type),
    		val: interface {}(*google.golang.org/grpc/peer.Peer) ...,},
    	key: (unreadable could not resolve interface type),
    	val: interface {}(google.golang.org/grpc/metadata.MD) [
    		":authority": [
    			"doesn't matter done by dialer",
    		], 
    		"content-type": [
    			"application/grpc",
    		], 
    		"user-agent": [
    			"grpc-go/1.35.0",
    		], 
    	],}
    (dlv) p ctx.val.ctx.Context
    context.Context(*context.valueCtx) *{
    	Context: context.Context(*context.cancelCtx) *{
    		Context: context.Context(*context.emptyCtx) ...,
    		mu: (*sync.Mutex)(0xc00037ebd0),
    		done: (*"sync/atomic.Value")(0xc00037ebd8),
    		children: map[context.canceler]struct {} nil,
    		err: error nil,},
    	key: (unreadable could not resolve interface type),
    	val: interface {}(*google.golang.org/grpc/peer.Peer) *{
    		Addr: net.Addr nil,
    		AuthInfo: google.golang.org/grpc/credentials.AuthInfo(*github.com/zrepl/zrepl/rpc/grpcclientidentity.authConnAuthType) ...,},}
    (dlv) p ctx.val.ctx.Context.val
    interface {}(*google.golang.org/grpc/peer.Peer) *{
    	Addr: net.Addr nil,
    	AuthInfo: google.golang.org/grpc/credentials.AuthInfo(*github.com/zrepl/zrepl/rpc/grpcclientidentity.authConnAuthType) *{
    		clientIdentity: "local_backup",},}
    

    There we go. The underlying Addr field is indeed nil.

    So who is supposed to set the peer.Peer value?
    Good thing we just need to look for callers of peer.NewContext within the gRPC source code.
    (zrepl is using google.colang.org/[email protected])

    A quick [SourceGraph search(https://sourcegraph.com/search?q=context:global+repo:%5Egithub%5C.com/grpc/grpc-go%24%40v1.35.0+peer.NewContext&patternType=literal) reveals three places that are particularly relevant:

    My gut feeling is that, for our code path, the first one is most relevant.
    It calls .RemoteAddr() to get the net.Addr which is nil in your case, but usually (Linux, FreeBSD) it's != nil.


    Where to go from here?

    Here are a few experiments to run.
    Please report if the daemon crashes or not, and if it crashes, please upload the binary & core files into correspondingly named directories on the web share that I sent you.

    1. transport_tcp:
      Use a 127.0.0.1 TCP listener (zrepl transport type tcp) instead of the local transport.

    2. go117:
      Use Go 1.17 to compile the package.

    3. zrepl_0.4:
      Use Go 1.18 with zrepl 0.4.

    If you can't do some of the experiments, just do the ones you can and report back. The most important one is transport_tcp.

  14. 6 remaining items

  15. jgmills commented on Jul 5, 2022

    @jgmills
    Author

    I can give you access to one of my servers, although it may take me some time to set this up. It's a bit complicated because it's a two-step process. First you would ssh to an IP address. That would mean that you login to my main server. Then you connect to one of the servers on my private network, where you can do your debugging. I may be able to automate the two-step part. How much disk space do you need?

    Alternatively, you can download an image from https://www.openindiana.org/download/. OI is an illumos distro. I'd recommend the live USB image. These will boot and install to a virtual disk from a variety of virtualization platforms. The version available from that web page is 2021-10 . I'm running 2022-05 on my development server, making it only 7 months newer. That should be fine. Will that way be suitable for you?

  16. jgmills commented on Jul 6, 2022

    @jgmills
    Author

    The download link above should be https://www.openindiana.org/download/ .

  17. problame commented on Jul 6, 2022

    @problame
    Member

    I created a VM and am able to reproduce the crash.

  18. jgmills commented on Jul 6, 2022

    @jgmills
    Author

    That's excellent news. illumos does have a socketpair function, so I'd guess that the zrepl source is doing something wrong. Here's the man page:

    NAME
           socketpair - create a pair of connected sockets
    
    SYNOPSIS
           cc [ flag ... ] file ... -lsocket  -lnsl  [ library ... ]
           #include <sys/types.h>                                                   
           #include <sys/socket.h>                                                  
    
           int socketpair(int domain, int type, int protocol, int sv[2]);
    
    DESCRIPTION
           The socketpair() library call creates an unnamed pair of connected
           sockets in the specified address family domain, of the specified type,
           that uses the optionally specified protocol. The descriptors that are
           used in referencing the new sockets are returned in sv[0] and sv[1].
           The two sockets are indistinguishable.
    
    RETURN VALUES
           socketpair() returns −1 on failure and 0        on success.
    
    ERRORS
           The call succeeds unless:
    ...
    
    NOTES
           This call is currently implemented only for the AF_UNIX address family.
    
    
  19. problame commented on Jul 7, 2022

    @problame
    Member

    I have opened the following bug against the Go stdlib: golang/go#53739

    tl;dr: getpeername doesn't work from Go on socketpair sockets. That's why .RemoteAddr() returns nil. And that's what leads to the panic, because gRPC / zrepl expect it to be not nil.

    I have no idea who exactly is at fault here, but it seems like Illumos is quite alone in not returning a RemoteAddr in this case.

    Anyways, I guess the workaround will be to check for != nil first, and hope we only look at it in this specific place where it crashes.

  20. problame commented on Jul 7, 2022

    @problame
    Member

    Validated the commit on my OpenIndiana VM. @jgmills please try it out and report back.

  21. jgmills commented on Jul 8, 2022

    @jgmills
    Author

    I'm curious what the return value of getpeername is, and if it is non-zero, what the value of errno is. Typically, you should check for successful invocation of the function, before you examine any of the function parameters. On illumos, I'm guessing that a socket pair is actually a pipe, and the peer may not have a name. The man page for getpeername on illumos is shown below:

    NAME
           getpeername - get name of connected peer
    
    SYNOPSIS
           cc [ flag ... ] file ... -lsocket  -lnsl  [ library ... ]
           #include <sys/types.h>                                                   
           #include <sys/socket.h>                                                  
    
           int getpeername(int s, struct sockaddr *name, socklen_t *namelen);
    
    
    DESCRIPTION
           getpeername() returns the name of the peer connected to socket s.  The
           int pointed to by the namelen parameter should be initialized to
           indicate the amount of space pointed to by name. On return it contains
           the actual size of the name returned (in bytes), prior to any
           truncation. The name is truncated if the buffer provided is too small.
    
    RETURN VALUES
           If successful, getpeername() returns  0; otherwise it returns −1 and
           sets errno to indicate the error.
    
    ERRORS
    ...
    
  22. problame commented on Jul 8, 2022

    @problame
    Member

    Well, that's the thing. From C, getpeername returns 0, and everything is all right.
    But from Go, syscall.Getpeername returns an error.
    My gut feeling is that something in Go is wrong, though.

    However, for all practical purposes, we're going to have to work around this in zrepl.
    Were you able to test the patch above?

  23. jgmills commented on Jul 9, 2022

    @jgmills
    Author

    I'm pleased to report that, with the patch, the local RPC transport worked: the daemon did not crash. As far as I could tell, the daemon operated normally.

  24. problame commented on Jul 10, 2022

    @problame
    Member

    Cool, I'll merge it then.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Type

    No type

    Projects

    No projects

      Milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions