You signed in with another tab or window. Reload to refresh your session.You signed out in another tab or window. Reload to refresh your session.You switched accounts on another tab or window. Reload to refresh your session.Dismiss alert
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?
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:
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.
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.
(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/
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)
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:
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?
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.
transport_tcp:
Use a 127.0.0.1 TCP listener (zrepl transport type tcp) instead of the local transport.
go117:
Use Go 1.17 to compile the package.
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.
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?
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.
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.
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
...
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?
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.
Activity
problame commentedon May 7, 2022
So, the offending line is
zrepl/rpc/grpcclientidentity/authlistener_grpc_adaptor.go
Line 121 in efe7b17
I'm pretty sure
logger != nil, but not so sure aboutpwhich is returned from gRPC'speerpackage.That code returns
!= nilon 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
jgmills commentedon May 8, 2022
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.
jgmills commentedon May 14, 2022
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.
problame commentedon May 15, 2022
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
dlvdebugger 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/
jgmills commentedon May 15, 2022
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:
problame commentedon Jun 19, 2022
My conclusion from this output is still the same as above.
We're using
socketpairto implement thelocaltransport 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.
jgmills commentedon Jun 20, 2022
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:
As you can see, it's not very useful for this core dump.
jgmills commentedon Jun 24, 2022
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?
problame commentedon Jun 25, 2022
Sent an upload link to you via email.
jgmills commentedon Jun 25, 2022
Thanks. I uploaded zrepl.core to that location.
problame commentedon Jun 27, 2022
Would you please upload the zrepl binary to that location as well?
jgmills commentedon Jun 27, 2022
I just uploaded this file:
problame commentedon Jun 27, 2022
Quick glimpse at the core dump confirms that
pisnil:So, why did
p, ok := peer.FromContext(ctx)returnnil, ok?Let's inspect the local
ctx, which for some reason doesn't show up in dlv'slocalsoutput, but is still accessible:There we go. The underlying
Addrfield is indeed nil.So who is supposed to set the
peer.Peervalue?Good thing we just need to look for callers of
peer.NewContextwithin 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 thenet.Addrwhich isnilin 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.
transport_tcp:Use a 127.0.0.1 TCP listener (zrepl transport type
tcp) instead of thelocaltransport.go117:Use Go 1.17 to compile the package.
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.6 remaining items
jgmills commentedon Jul 5, 2022
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?
jgmills commentedon Jul 6, 2022
The download link above should be https://www.openindiana.org/download/ .
problame commentedon Jul 6, 2022
I created a VM and am able to reproduce the crash.
jgmills commentedon Jul 6, 2022
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:
problame commentedon Jul 7, 2022
I have opened the following bug against the Go stdlib: golang/go#53739
tl;dr:
getpeernamedoesn'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.
rpc/grpcclientidentity/authlistener_grpc_adaptor: don't assume peer.A…
problame commentedon Jul 7, 2022
Validated the commit on my OpenIndiana VM. @jgmills please try it out and report back.
jgmills commentedon Jul 8, 2022
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:
problame commentedon Jul 8, 2022
Well, that's the thing. From C,
getpeernamereturns 0, and everything is all right.But from Go,
syscall.Getpeernamereturns 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?
jgmills commentedon Jul 9, 2022
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.
problame commentedon Jul 10, 2022
Cool, I'll merge it then.
rpc/grpcclientidentity/authlistener_grpc_adaptor: don't assume peer.A…