search

lrstanley / girc

:bomb: girc is a flexible IRC library for Go :ok_hand:
https://pkg.go.dev/github.com/lrstanley/girc
MIT License
137 stars 13 forks source link

execLoop and sendLoop not getting closed if network connection is low-quality #50

Closed JeremyRand closed 1 year ago

JeremyRand commented 2 years ago

It appears that if a low-quality network connection (e.g. being behind a Whonix Tor transproxy) is being used, the execLoop and/or sendLoop goroutines aren't reliably being closed properly after a disconnect.

Originally reported at https://github.com/42wim/matterbridge/issues/1743 (detailed logs are in that issue) ; @42wim suggested that I report it here. I'm happy to help with trying to narrow down the bug, e.g. by collecting more detailed logs, but my ability to help may be limited since I'm not the author of the affected software. In any event please let me know what I can do to help get this fixed.

lrstanley commented 2 years ago

I believe I've figured out what the issue is, and put a potential patch in with https://github.com/lrstanley/girc/commit/887ab30b9028c8c8f178aa73dcac50366a681052 -- if @42wim can make a temporary build with these changes, to test things out, that would help.

If the issue is still occurring, I'd likely need a goroutine dump during the hang to be able to best troubleshoot it. That would help determine what is causing the goroutine(s) to hang.

42wim commented 2 years ago

@lrstanley thanks for taking a look! @JeremyRand you can find binaries with the patch in on https://github.com/42wim/matterbridge/actions/runs/2019172615 or build from https://github.com/42wim/matterbridge/pull/1773

JeremyRand commented 2 years ago

Thanks @lrstanley ! I'm testing out the fix now; will get back to you in a few days with results.

JeremyRand commented 2 years ago

@lrstanley Unfortunately it still hangs at what looks like the same place. I'm not familiar with how to get a goroutine dump, but will look for docs and let you know if I need instructions.

nmeum commented 2 years ago

I'm not familiar with how to get a goroutine dump, but will look for docs and let you know if I need instructions.

Just send a SIGQUIT to the process, that should output a full stack trace for all goroutines.

lrstanley commented 2 years ago

I've fixed another lock-related bug in https://github.com/lrstanley/girc/commit/40b9ac84de1e7f391c5835078262f73e71df7cd0, which may be related.

42wim commented 2 years ago

@lrstanley thanks!

@JeremyRand I've made a PR containing the updated dependencies https://github.com/42wim/matterbridge/pull/1800 You can also just run go install github.com/42wim/matterbridge@fe8a75b976387de9dff017249920c2cfe3f4d926 which will install it in ~/go/bin/matterbridge

JeremyRand commented 2 years ago

Thanks, will try the updated version and let you know how it goes.

42wim commented 2 years ago

@JeremyRand any updates?

JeremyRand commented 2 years ago

Been occupied with $DAYJOB, will try to get to this ASAP. Sorry for the delays.

lrstanley commented 2 years ago

Just to remind myself, I think I'm going to switch to a errgroup based approach for some of the logic that was adjusted in 40b9ac84de1e7f391c5835078262f73e71df7cd0, rather than the sync.WaitGroup + channel method that girc currently does. This should hopefully make the code a bit cleaner.

JeremyRand commented 2 years ago

Here's a goroutine dump of the hang, with Matterbridge 81e6f75aa491c7bfa11780dd622587cf5fff3c8f:

time="2022-05-05T05:28:18Z" level=info msg="debug:05:28:18 conn.go:367: waiting for all routines to finish" prefix=irc
SIGQUIT: quit
PC=0x100d7080 m=0 sigcode=0

goroutine 22 [syscall, 2 minutes]:
syscall.Syscall6(0xee, 0x7, 0xc00080fbe0, 0x7, 0xffffffffffffffff, 0x0, 0x0)
    /usr/local/go/src/syscall/asm_linux_ppc64x.s:41 +0xc fp=0xc00080faf0 sp=0xc00080fad0 pc=0x100d705c
golang.org/x/sys/unix.Syscall6(...)
    /home/user/go/src/github.com/42wim/matterbridge/vendor/golang.org/x/sys/unix/syscall_unix_gc_ppc64x.go:18
golang.org/x/sys/unix.EpollWait(0x7, {0xc00080fbe0, 0x7, 0x7}, 0xffffffffffffffff)
    /home/user/go/src/github.com/42wim/matterbridge/vendor/golang.org/x/sys/unix/zsyscall_linux_ppc64le.go:56 +0x68 fp=0x
c00080fb68 sp=0xc00080faf0 pc=0x10132558
github.com/fsnotify/fsnotify.(*fdPoller).wait(0xc0000e2220)
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/fsnotify/fsnotify/inotify_poller.go:86 +0x7c fp=0xc
00080fc58 sp=0xc00080fb68 pc=0x1013416c
github.com/fsnotify/fsnotify.(*Watcher).readEvents(0xc0002c4b40)
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/fsnotify/fsnotify/inotify.go:206 +0x280 fp=0xc00081
ffb0 sp=0xc00080fc58 pc=0x10133430
runtime.goexit()
    /usr/local/go/src/runtime/asm_ppc64x.s:856 +0x4 fp=0xc00081ffb0 sp=0xc00081ffb0 pc=0x10081f64
created by github.com/fsnotify/fsnotify.NewWatcher
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/fsnotify/fsnotify/inotify.go:60 +0x1d4

goroutine 1 [select (no cases), 2467 minutes]:
main.main()
    /home/user/go/src/github.com/42wim/matterbridge/matterbridge.go:69 +0x504

goroutine 21 [semacquire, 2469 minutes]:
sync.runtime_Semacquire(0xc0002837f8)
    /usr/local/go/src/runtime/sema.go:56 +0x3c
sync.(*WaitGroup).Wait(0xc0002837f0)
    /usr/local/go/src/sync/waitgroup.go:130 +0xa8
github.com/spf13/viper.(*Viper).WatchConfig.func1(0xc00012a000, 0xc0002837e0)
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/spf13/viper/viper.go:495 +0x2bc
created by github.com/spf13/viper.(*Viper).WatchConfig
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/spf13/viper/viper.go:434 +0x70

goroutine 23 [select, 885 minutes]:
github.com/spf13/viper.(*Viper).WatchConfig.func1.1(0xc0002c4b40, 0xc0002837f0, {0x11d4e1ec, 0x11}, {0x11d4e1ec, 0x11}, 0xc00
07b2430, 0xc00012a000)
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/spf13/viper/viper.go:456 +0x98
created by github.com/spf13/viper.(*Viper).WatchConfig.func1
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/spf13/viper/viper.go:454 +0x27c

goroutine 5 [semacquire, 1368 minutes]:
sync.runtime_Semacquire(0xc0002826f8)
    /usr/local/go/src/runtime/sema.go:56 +0x3c
sync.(*WaitGroup).Wait(0xc0002826f0)
    /usr/local/go/src/sync/waitgroup.go:130 +0xa8
github.com/lrstanley/girc.(*Client).internalConnect(0xc000001a00, {0x0, 0x0}, {0x0, 0x0})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/conn.go:370 +0xe6c
github.com/lrstanley/girc.(*Client).Connect(...)
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/conn.go:199
github.com/42wim/matterbridge/bridge/irc.(*Birc).doConnect(0xc0003ea7e0)
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/irc.go:193 +0x80
created by github.com/42wim/matterbridge/bridge/irc.(*Birc).Connect
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/irc.go:101 +0x5a0

goroutine 1168 [chan receive, 1438 minutes]:
github.com/42wim/matterbridge/bridge/irc.(*Birc).doSend(0xc0003eaea0)
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/irc.go:227 +0xa0
created by github.com/42wim/matterbridge/bridge/irc.(*Birc).Connect
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/irc.go:112 +0x70c

goroutine 910 [semacquire, 885 minutes]:
sync.runtime_Semacquire(0xc000c20198)
    /usr/local/go/src/runtime/sema.go:56 +0x3c
sync.(*WaitGroup).Wait(0xc000c20190)
    /usr/local/go/src/sync/waitgroup.go:130 +0xa8
github.com/lrstanley/girc.(*Client).internalConnect(0xc000adfba0, {0x0, 0x0}, {0x0, 0x0})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/conn.go:370 +0xe6c
github.com/lrstanley/girc.(*Client).Connect(...)
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/conn.go:199
github.com/42wim/matterbridge/bridge/irc.(*Birc).doConnect(0xc0003eaea0)
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/irc.go:193 +0x80
created by github.com/42wim/matterbridge/bridge/irc.(*Birc).Connect
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/irc.go:101 +0x5a0

goroutine 13965 [chan send, 1370 minutes]:
github.com/42wim/matterbridge/bridge/irc.(*Birc).handlePrivMsg(0xc0003ea7e0, 0xc000001a00, {0xc000c360f0, 0x0, {0xc094d983813
cf73f, 0x3bfa14fd7713, 0x13524bc0}, {0xc0007f2756, 0x6}, {0xc003148860, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/handlers.go:241 +0x9e8
github.com/42wim/matterbridge/bridge/irc.(*Birc).handleNotice(0xc0003ea7e0, 0xc000001a00, {0xc000c360f0, 0x0, {0xc094d983813c
f73f, 0x3bfa14fd7713, 0x13524bc0}, {0xc0007f2756, 0x6}, {0xc003148860, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/handlers.go:154 +0x12c
github.com/lrstanley/girc.HandlerFunc.Execute(0xc000a14450, 0xc000001a00, {0xc000c360f0, 0x0, {0xc094d983813cf73f, 0x3bfa14fd
7713, 0x13524bc0}, {0xc0007f2756, 0x6}, {0xc003148860, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:67 +0x78
github.com/lrstanley/girc.(*Caller).exec.func1.1(0xc000001a00, 0xc000b64960, 0xc002cc6570, 0x0, 0xc000846ba0, {0xc094d9838146
49e9, 0x3bfa1506c9bd, 0x13524bc0})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:220 +0x168
created by github.com/lrstanley/girc.(*Caller).exec.func1
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:215 +0x4c8

goroutine 16050 [chan send, 887 minutes]:
github.com/42wim/matterbridge/bridge/irc.(*Birc).handlePrivMsg(0xc0003eaea0, 0xc000adfba0, {0xc000a16f90, 0x0, {0xc094f5df4dd
09f82, 0x5664253bdba4, 0x13524bc0}, {0xc00065a592, 0x6}, {0xc0031481c0, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/handlers.go:241 +0x9e8
github.com/42wim/matterbridge/bridge/irc.(*Birc).handleNotice(0xc0003eaea0, 0xc000adfba0, {0xc000a16f90, 0x0, {0xc094f5df4dd0
9f82, 0x5664253bdba4, 0x13524bc0}, {0xc00065a592, 0x6}, {0xc0031481c0, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/handlers.go:154 +0x12c
github.com/lrstanley/girc.HandlerFunc.Execute(0xc002b65530, 0xc000adfba0, {0xc000a16f90, 0x0, {0xc094f5df4dd09f82, 0x5664253b
dba4, 0x13524bc0}, {0xc00065a592, 0x6}, {0xc0031481c0, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:67 +0x78
github.com/lrstanley/girc.(*Caller).exec.func1.1(0xc000adfba0, 0xc00310dc80, 0xc000a26378, 0x0, 0xc00082d230, {0xc094f5df4dd5
9ddd, 0x56642540d9fc, 0x13524bc0})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:220 +0x168
created by github.com/lrstanley/girc.(*Caller).exec.func1
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:215 +0x4c8

goroutine 16140 [chan send, 887 minutes]:
github.com/42wim/matterbridge/bridge/irc.(*Birc).handlePrivMsg(0xc0003eaea0, 0xc000adfba0, {0xc000c36930, 0x0, {0xc094f5df4dd
187ea, 0x5664253cc3d6, 0x13524bc0}, {0xc00065a652, 0x6}, {0xc0031489c0, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/handlers.go:241 +0x9e8
github.com/42wim/matterbridge/bridge/irc.(*Birc).handleNotice(0xc0003eaea0, 0xc000adfba0, {0xc000c36930, 0x0, {0xc094f5df4dd1
87ea, 0x5664253cc3d6, 0x13524bc0}, {0xc00065a652, 0x6}, {0xc0031489c0, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/handlers.go:154 +0x12c
github.com/lrstanley/girc.HandlerFunc.Execute(0xc002b65530, 0xc000adfba0, {0xc000c36930, 0x0, {0xc094f5df4dd187ea, 0x5664253c
c3d6, 0x13524bc0}, {0xc00065a652, 0x6}, {0xc0031489c0, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:67 +0x78
github.com/lrstanley/girc.(*Caller).exec.func1.1(0xc000adfba0, 0xc000b64780, 0xc000a267b0, 0x0, 0xc00082d230, {0xc094f5df4df5
5a7a, 0x566425609675, 0x13524bc0})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:220 +0x168
created by github.com/lrstanley/girc.(*Caller).exec.func1
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:215 +0x4c8

goroutine 322 [chan receive, 1438 minutes]:
github.com/42wim/matterbridge/bridge/irc.(*Birc).doSend(0xc0003ea7e0)
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/irc.go:227 +0xa0
created by github.com/42wim/matterbridge/bridge/irc.(*Birc).Connect
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/irc.go:112 +0x70c

goroutine 1169 [chan send, 1368 minutes]:
github.com/lrstanley/girc.(*Client).write(0xc000001a00, 0xc00310daa0)
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/conn.go:471 +0xb8
github.com/lrstanley/girc.(*Client).Send(0xc000001a00, 0xc00310daa0)
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/conn.go:457 +0x284
github.com/lrstanley/girc.(*Commands).Join(0xc00083e1a0, {0xc000021928, 0x1, 0x1})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/commands.go:47 +0x2b0
github.com/42wim/matterbridge/bridge/irc.(*Birc).JoinChannel(0xc0003ea7e0, {{0xc0004510f0, 0xd}, {0xc0004510c0, 0xb}, {0x11d2
1882, 0x5}, {0xc0000f1410, 0x18}, 0xc0007bd680, ...})
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/irc.go:135 +0x290
github.com/42wim/matterbridge/bridge.(*Bridge).joinChannels(0xc0007b4180, 0xc0007875c0, 0xc000c59fb0)
    /home/user/go/src/github.com/42wim/matterbridge/bridge/bridge.go:79 +0x274
github.com/42wim/matterbridge/bridge.(*Bridge).JoinChannels(...)
    /home/user/go/src/github.com/42wim/matterbridge/bridge/bridge.go:64
github.com/42wim/matterbridge/gateway.(*Router).handleEventRejoinChannels(0xc0002c4b90, 0xc0005928f0)
    /home/user/go/src/github.com/42wim/matterbridge/gateway/handlers.go:61 +0x1ec
github.com/42wim/matterbridge/gateway.(*Router).handleReceive(0xc0002c4b90)
    /home/user/go/src/github.com/42wim/matterbridge/gateway/router.go:135 +0x1b8
created by github.com/42wim/matterbridge/gateway.(*Router).Start
    /home/user/go/src/github.com/42wim/matterbridge/gateway/router.go:102 +0x6a0

goroutine 14167 [chan send, 1370 minutes]:
github.com/42wim/matterbridge/bridge/irc.(*Birc).doConnect.func1(0xc000001a00, {0xc000c18d80, 0x0, {0xc094d991643de7a6, 0x3c0
7063fcd7a, 0x13524bc0}, {0xc000b954a6, 0x3}, {0xc00002f8c0, 0x2, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/irc.go:206 +0x9c
github.com/lrstanley/girc.HandlerFunc.Execute(0xc000a98360, 0xc000001a00, {0xc000c18d80, 0x0, {0xc094d991643de7a6, 0x3c07063f
cd7a, 0x13524bc0}, {0xc000b954a6, 0x3}, {0xc00002f8c0, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:67 +0x78
github.com/lrstanley/girc.(*Caller).exec.func1(0xc0033774a0, 0xc000846ba0, 0xc000a26e28, {0xc000b954a6, 0x3}, 0x0, 0xc000001a
00, 0xc000a43aa0, 0x0)
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:231 +0x2cc
created by github.com/lrstanley/girc.(*Caller).exec
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:209 +0x73c

goroutine 832 [chan send, 1166 minutes]:
github.com/42wim/matterbridge/bridge/matrix.(*Bmatrix).handleEvent(0xc0003ead80, 0xc003174100)
    /home/user/go/src/github.com/42wim/matterbridge/bridge/matrix/matrix.go:523 +0x980
github.com/matterbridge/gomatrix.(*DefaultSyncer).notifyListeners(0xc000c19800, 0xc003174100)
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/matterbridge/gomatrix/sync.go:156 +0xcc
github.com/matterbridge/gomatrix.(*DefaultSyncer).ProcessResponse(0xc000c19800, 0xc00310c060, {0xc0031aa360, 0x58})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/matterbridge/gomatrix/sync.go:65 +0xa64
github.com/matterbridge/gomatrix.(*Client).Sync(0xc000bee000)
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/matterbridge/gomatrix/client.go:153 +0x2d0
github.com/42wim/matterbridge/bridge/matrix.(*Bmatrix).handlematrix.func1(0xc0003ead80)
    /home/user/go/src/github.com/42wim/matterbridge/bridge/matrix/matrix.go:381 +0x38
created by github.com/42wim/matterbridge/bridge/matrix.(*Bmatrix).handlematrix
    /home/user/go/src/github.com/42wim/matterbridge/bridge/matrix/matrix.go:376 +0x608

goroutine 16027 [semacquire, 887 minutes]:
sync.runtime_Semacquire(0xc002f0c008)
    /usr/local/go/src/runtime/sema.go:56 +0x3c
sync.(*WaitGroup).Wait(0xc002f0c000)
    /usr/local/go/src/sync/waitgroup.go:130 +0xa8
github.com/lrstanley/girc.(*Caller).exec(0xc00082d230, {0xc002dcc852, 0x3}, 0x0, 0xc000adfba0, 0xc000b65f80)
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:238 +0x760
github.com/lrstanley/girc.(*Client).RunHandlers(0xc000adfba0, 0xc000b64de0)
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:45 +0x2e8
github.com/lrstanley/girc.(*Client).execLoop(0xc000adfba0, {0x11fb4d58, 0xc0032420c0}, 0xc00310c5a0, 0xc000c20190)
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/client.go:424 +0xdc
created by github.com/lrstanley/girc.(*Client).internalConnect
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/conn.go:304 +0x3ac

goroutine 13957 [chan send, 1370 minutes]:
github.com/42wim/matterbridge/bridge/irc.(*Birc).handlePrivMsg(0xc0003ea7e0, 0xc000001a00, {0xc000ac7e00, 0x0, {0xc094d983813
9bb94, 0x3bfa14fa3b7d, 0x13524bc0}, {0xc0008bca16, 0x6}, {0xc0031485e0, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/handlers.go:241 +0x9e8
github.com/42wim/matterbridge/bridge/irc.(*Birc).handleNotice(0xc0003ea7e0, 0xc000001a00, {0xc000ac7e00, 0x0, {0xc094d9838139
bb94, 0x3bfa14fa3b7d, 0x13524bc0}, {0xc0008bca16, 0x6}, {0xc0031485e0, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/handlers.go:154 +0x12c
github.com/lrstanley/girc.HandlerFunc.Execute(0xc000a14450, 0xc000001a00, {0xc000ac7e00, 0x0, {0xc094d9838139bb94, 0x3bfa14fa
3b7d, 0x13524bc0}, {0xc0008bca16, 0x6}, {0xc0031485e0, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:67 +0x78
github.com/lrstanley/girc.(*Caller).exec.func1.1(0xc000001a00, 0xc000b64540, 0xc002cc6498, 0x0, 0xc000846ba0, {0xc094d9838142
1719, 0x3bfa150296f6, 0x13524bc0})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:220 +0x168
created by github.com/lrstanley/girc.(*Caller).exec.func1
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:215 +0x4c8

goroutine 16095 [chan send, 887 minutes]:
github.com/42wim/matterbridge/bridge/irc.(*Birc).handlePrivMsg(0xc0003eaea0, 0xc000adfba0, {0xc000a17ad0, 0x0, {0xc094f5df4dd
1340b, 0x5664253c6ffd, 0x13524bc0}, {0xc00065a5d2, 0x6}, {0xc0031484c0, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/handlers.go:241 +0x9e8
github.com/42wim/matterbridge/bridge/irc.(*Birc).handleNotice(0xc0003eaea0, 0xc000adfba0, {0xc000a17ad0, 0x0, {0xc094f5df4dd1
340b, 0x5664253c6ffd, 0x13524bc0}, {0xc00065a5d2, 0x6}, {0xc0031484c0, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/handlers.go:154 +0x12c
github.com/lrstanley/girc.HandlerFunc.Execute(0xc002b65530, 0xc000adfba0, {0xc000a17ad0, 0x0, {0xc094f5df4dd1340b, 0x5664253c
6ffd, 0x13524bc0}, {0xc00065a5d2, 0x6}, {0xc0031484c0, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:67 +0x78
github.com/lrstanley/girc.(*Caller).exec.func1.1(0xc000adfba0, 0xc000b641e0, 0xc000a264f8, 0x0, 0xc00082d230, {0xc094f5df4de6
ed06, 0x5664255228e7, 0x13524bc0})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:220 +0x168
created by github.com/lrstanley/girc.(*Caller).exec.func1
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:215 +0x4c8

goroutine 16243 [chan send, 887 minutes]:
github.com/42wim/matterbridge/bridge/irc.(*Birc).doConnect.func1(0xc000adfba0, {0xc0002dbe90, 0x0, {0xc094f5df751d0f57, 0x566
44c884b41, 0x13524bc0}, {0xc002dcc852, 0x3}, {0xc003149760, 0x2, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/irc.go:206 +0x9c
github.com/lrstanley/girc.HandlerFunc.Execute(0xc000a98000, 0xc000adfba0, {0xc0002dbe90, 0x0, {0xc094f5df751d0f57, 0x56644c88
4b41, 0x13524bc0}, {0xc002dcc852, 0x3}, {0xc003149760, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:67 +0x78
github.com/lrstanley/girc.(*Caller).exec.func1(0xc002f0c000, 0xc00082d230, 0xc000a26cf0, {0xc002dcc852, 0x3}, 0x0, 0xc000adfb
a0, 0xc000b65f80, 0x0)
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:231 +0x2cc
created by github.com/lrstanley/girc.(*Caller).exec
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:209 +0x73c

goroutine 15565 [chan send, 1044 minutes]:
github.com/42wim/matterbridge/bridge/irc.(*Birc).handleJoinPart(0xc0003eaea0, 0xc000adfba0, {0xc000a16960, 0x0, {0xc094ecb8f1
5ffea8, 0x4dde0c5e7191, 0x13524bc0}, {0xc0008bc3ee, 0x4}, {0xc000a98bd0, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/handlers.go:114 +0x7e8
github.com/lrstanley/girc.HandlerFunc.Execute(0xc002b65830, 0xc000adfba0, {0xc000a16960, 0x0, {0xc094ecb8f15ffea8, 0x4dde0c5e
7191, 0x13524bc0}, {0xc0008bc3ee, 0x4}, {0xc000a98bd0, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:67 +0x78
github.com/lrstanley/girc.(*Caller).exec.func1.1(0xc000adfba0, 0xc00310c5a0, 0xc002cc6240, 0x0, 0xc00082d230, {0xc094ecb8f165
e981, 0x4dde0c645c45, 0x13524bc0})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:220 +0x168
created by github.com/lrstanley/girc.(*Caller).exec.func1
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:215 +0x4c8

goroutine 13569 [chan send, 1372 minutes]:
github.com/42wim/matterbridge/bridge/irc.(*Birc).handlePrivMsg(0xc0003ea7e0, 0xc000001a00, {0xc001c610b0, 0x0, {0xc094d97a4ea
a9d10, 0x3bf1850beb0b, 0x13524bc0}, {0xc000a667d6, 0x6}, {0xc0032adac0, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/handlers.go:241 +0x9e8
github.com/42wim/matterbridge/bridge/irc.(*Birc).handleNotice(0xc0003ea7e0, 0xc000001a00, {0xc001c610b0, 0x0, {0xc094d97a4eaa
9d10, 0x3bf1850beb0b, 0x13524bc0}, {0xc000a667d6, 0x6}, {0xc0032adac0, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/handlers.go:154 +0x12c
github.com/lrstanley/girc.HandlerFunc.Execute(0xc000a14450, 0xc000001a00, {0xc001c610b0, 0x0, {0xc094d97a4eaa9d10, 0x3bf1850b
eb0b, 0x13524bc0}, {0xc000a667d6, 0x6}, {0xc0032adac0, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:67 +0x78
github.com/lrstanley/girc.(*Caller).exec.func1.1(0xc000001a00, 0xc000a91920, 0xc0009ca648, 0x0, 0xc000846ba0, {0xc094d97a4eb2
65b0, 0x3bf18513b38f, 0x13524bc0})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:220 +0x168
created by github.com/lrstanley/girc.(*Caller).exec.func1
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:215 +0x4c8

goroutine 13869 [semacquire, 1370 minutes]:
sync.runtime_Semacquire(0xc0033774a8)
    /usr/local/go/src/runtime/sema.go:56 +0x3c
sync.(*WaitGroup).Wait(0xc0033774a0)
    /usr/local/go/src/sync/waitgroup.go:130 +0xa8
github.com/lrstanley/girc.(*Caller).exec(0xc000846ba0, {0xc000b954a6, 0x3}, 0x0, 0xc000001a00, 0xc000a43aa0)
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:238 +0x760
github.com/lrstanley/girc.(*Client).RunHandlers(0xc000001a00, 0xc000a42a80)
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:45 +0x2e8
github.com/lrstanley/girc.(*Client).execLoop(0xc000001a00, {0x11fb4d58, 0xc003242140}, 0xc000a685a0, 0xc0002826f0)
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/client.go:424 +0xdc
created by github.com/lrstanley/girc.(*Client).internalConnect
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/conn.go:304 +0x3ac

goroutine 16028 [chan send, 887 minutes]:
github.com/lrstanley/girc.(*Client).readLoop(0xc000adfba0, {0x11fb4d58, 0xc0032420c0}, 0xc00310c5a0, 0xc000c20190)
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/conn.go:424 +0xe4
created by github.com/lrstanley/girc.(*Client).internalConnect
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/conn.go:305 +0x3ec

goroutine 13972 [chan send, 1370 minutes]:
github.com/42wim/matterbridge/bridge/irc.(*Birc).handlePrivMsg(0xc0003ea7e0, 0xc000001a00, {0xc002d19f50, 0x0, {0xc094d98a554
99ceb, 0x3c00725d6ada, 0x13524bc0}, {0xc000948836, 0x6}, {0xc000b6ca40, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/handlers.go:241 +0x9e8
github.com/42wim/matterbridge/bridge/irc.(*Birc).handleNotice(0xc0003ea7e0, 0xc000001a00, {0xc002d19f50, 0x0, {0xc094d98a5549
9ceb, 0x3c00725d6ada, 0x13524bc0}, {0xc000948836, 0x6}, {0xc000b6ca40, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/handlers.go:154 +0x12c
github.com/lrstanley/girc.HandlerFunc.Execute(0xc000a14450, 0xc000001a00, {0xc002d19f50, 0x0, {0xc094d98a55499ceb, 0x3c00725d
6ada, 0x13524bc0}, {0xc000948836, 0x6}, {0xc000b6ca40, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:67 +0x78
github.com/lrstanley/girc.(*Caller).exec.func1.1(0xc000001a00, 0xc0000c8600, 0xc000a266d8, 0x0, 0xc000846ba0, {0xc094d98a554d
5da6, 0x3c0072612b74, 0x13524bc0})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:220 +0x168
created by github.com/lrstanley/girc.(*Caller).exec.func1
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:215 +0x4c8

goroutine 16036 [chan send, 887 minutes]:
github.com/42wim/matterbridge/bridge/irc.(*Birc).handlePrivMsg(0xc0003eaea0, 0xc000adfba0, {0xc000ac7080, 0x0, {0xc094f5df4e7
54768, 0x566425e0835c, 0x13524bc0}, {0xc000a67992, 0x6}, {0xc0032ac720, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/handlers.go:241 +0x9e8
github.com/42wim/matterbridge/bridge/irc.(*Birc).handleNotice(0xc0003eaea0, 0xc000adfba0, {0xc000ac7080, 0x0, {0xc094f5df4e75
4768, 0x566425e0835c, 0x13524bc0}, {0xc000a67992, 0x6}, {0xc0032ac720, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/handlers.go:154 +0x12c
github.com/lrstanley/girc.HandlerFunc.Execute(0xc002b65530, 0xc000adfba0, {0xc000ac7080, 0x0, {0xc094f5df4e754768, 0x566425e0
835c, 0x13524bc0}, {0xc000a67992, 0x6}, {0xc0032ac720, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:67 +0x78
github.com/lrstanley/girc.(*Caller).exec.func1.1(0xc000adfba0, 0xc000a68f60, 0xc002cc65b8, 0x0, 0xc00082d230, {0xc094f5df4e80
7fed, 0x566425ebbbe3, 0x13524bc0})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:220 +0x168
created by github.com/lrstanley/girc.(*Caller).exec.func1
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:215 +0x4c8

goroutine 909 [select, 885 minutes]:
io.(*pipe).Read(0xc0009430e0, {0xc00059e1a2, 0xe5e, 0xe5e})
    /usr/local/go/src/io/pipe.go:57 +0xa8
io.(*PipeReader).Read(0xc00083e2d8, {0xc00059e1a2, 0xe5e, 0xe5e})
    /usr/local/go/src/io/pipe.go:134 +0x48
bufio.(*Scanner).Scan(0xc00085df20)
    /usr/local/go/src/bufio/scan.go:215 +0xa7c
github.com/sirupsen/logrus.(*Entry).writerScanner(0xc00045ca10, 0xc00083e2d8, 0xc000b9e580)
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/sirupsen/logrus/writer.go:59 +0xa8
created by github.com/sirupsen/logrus.(*Entry).WriterLevel
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/sirupsen/logrus/writer.go:51 +0x460

goroutine 13948 [chan send, 1370 minutes]:
github.com/42wim/matterbridge/bridge/irc.(*Birc).handleJoinPart(0xc0003eaea0, 0xc000adfba0, {0xc000ac6600, 0x0, {0xc094d9816e
ec96cc, 0x3bf82a3bfcc1, 0x13524bc0}, {0xc002dcc035, 0x4}, {0xc0009f4430, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/handlers.go:114 +0x7e8
github.com/lrstanley/girc.HandlerFunc.Execute(0xc002b65830, 0xc000adfba0, {0xc000ac6600, 0x0, {0xc094d9816eec96cc, 0x3bf82a3b
fcc1, 0x13524bc0}, {0xc002dcc035, 0x4}, {0xc0009f4430, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:67 +0x78
github.com/lrstanley/girc.(*Caller).exec.func1.1(0xc000adfba0, 0xc0006a23c0, 0xc002cc60d8, 0x0, 0xc00082d230, {0xc094d9816ef2
a3b5, 0x3bf82a4209be, 0x13524bc0})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:220 +0x168
created by github.com/lrstanley/girc.(*Caller).exec.func1
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:215 +0x4c8

goroutine 13701 [chan send, 1372 minutes]:
github.com/42wim/matterbridge/bridge/irc.(*Birc).handlePrivMsg(0xc0003ea7e0, 0xc000001a00, {0xc001c61230, 0x0, {0xc094d97a4ea
bf4ff, 0x3bf1850d42ca, 0x13524bc0}, {0xc000924d86, 0x6}, {0xc0032adc40, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/handlers.go:241 +0x9e8
github.com/42wim/matterbridge/bridge/irc.(*Birc).handleNotice(0xc0003ea7e0, 0xc000001a00, {0xc001c61230, 0x0, {0xc094d97a4eab
f4ff, 0x3bf1850d42ca, 0x13524bc0}, {0xc000924d86, 0x6}, {0xc0032adc40, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/handlers.go:154 +0x12c
github.com/lrstanley/girc.HandlerFunc.Execute(0xc000a14450, 0xc000001a00, {0xc001c61230, 0x0, {0xc094d97a4eabf4ff, 0x3bf1850d
42ca, 0x13524bc0}, {0xc000924d86, 0x6}, {0xc0032adc40, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:67 +0x78
github.com/lrstanley/girc.(*Caller).exec.func1.1(0xc000001a00, 0xc000a91c20, 0xc0009ca6d8, 0x0, 0xc000846ba0, {0xc094d97a4eb4
4403, 0x3bf1851591c1, 0x13524bc0})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:220 +0x168
created by github.com/lrstanley/girc.(*Caller).exec.func1
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:215 +0x4c8

goroutine 13961 [chan send, 1370 minutes]:
github.com/42wim/matterbridge/bridge/irc.(*Birc).handlePrivMsg(0xc0003ea7e0, 0xc000001a00, {0xc000ac7f20, 0x0, {0xc094d983813
cbcef, 0x3bfa14fd3cbf, 0x13524bc0}, {0xc0007f2716, 0x6}, {0xc003148760, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/handlers.go:241 +0x9e8
github.com/42wim/matterbridge/bridge/irc.(*Birc).handleNotice(0xc0003ea7e0, 0xc000001a00, {0xc000ac7f20, 0x0, {0xc094d983813c
bcef, 0x3bfa14fd3cbf, 0x13524bc0}, {0xc0007f2716, 0x6}, {0xc003148760, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/handlers.go:154 +0x12c
github.com/lrstanley/girc.HandlerFunc.Execute(0xc000a14450, 0xc000001a00, {0xc000ac7f20, 0x0, {0xc094d983813cbcef, 0x3bfa14fd
3cbf, 0x13524bc0}, {0xc0007f2716, 0x6}, {0xc003148760, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:67 +0x78
github.com/lrstanley/girc.(*Caller).exec.func1.1(0xc000001a00, 0xc000b64720, 0xc002cc64f8, 0x0, 0xc000846ba0, {0xc094d9838144
d12c, 0x3bfa150550f2, 0x13524bc0})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:220 +0x168
created by github.com/lrstanley/girc.(*Caller).exec.func1
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:215 +0x4c8

goroutine 15500 [chan send, 1050 minutes]:
github.com/42wim/matterbridge/bridge/irc.(*Birc).handleJoinPart(0xc0003eaea0, 0xc000adfba0, {0xc000c36390, 0x0, {0xc094ec5852
58514a, 0x4d840df2302f, 0x13524bc0}, {0xc00094834f, 0x4}, {0xc000a98300, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/bridge/irc/handlers.go:114 +0x7e8
github.com/lrstanley/girc.HandlerFunc.Execute(0xc002b65630, 0xc000adfba0, {0xc000c36390, 0x0, {0xc094ec585258514a, 0x4d840df2
302f, 0x13524bc0}, {0xc00094834f, 0x4}, {0xc000a98300, ...}, ...})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:67 +0x78
github.com/lrstanley/girc.(*Caller).exec.func1.1(0xc000adfba0, 0xc00310c120, 0xc002cc6090, 0x0, 0xc00082d230, {0xc094ec58525e
bd44, 0x4d840df89c05, 0x13524bc0})
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:220 +0x168
created by github.com/lrstanley/girc.(*Caller).exec.func1
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/handler.go:215 +0x4c8

goroutine 13870 [chan send, 1370 minutes]:
github.com/lrstanley/girc.(*Client).readLoop(0xc000001a00, {0x11fb4d58, 0xc003242140}, 0xc000a685a0, 0xc0002826f0)
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/conn.go:424 +0xe4
created by github.com/lrstanley/girc.(*Client).internalConnect
    /home/user/go/src/github.com/42wim/matterbridge/vendor/github.com/lrstanley/girc/conn.go:305 +0x3ec

r0   0xee   r1   0xc00080fad0
r2   0x0    r3   0x4
r4   0xc00080fbe0   r5   0x7
r6   0xffffffffffffffff r7   0x0
r8   0x0    r9   0x0
r10  0x0    r11  0x0
r12  0x0    r13  0x7fffabaec310
r14  0x1004ecc4 r15  0xc00080fa08
r16  0x0    r17  0x1
r18  0x1    r19  0x0
r20  0xc00080fc40   r21  0x13525b00
r22  0x1    r23  0x8
r24  0x0    r25  0x0
r26  0x10081f64 r27  0x0
r28  0x12b5db10 r29  0x188f987
r30  0xc000277a00   r31  0x100d705c
pc   0x100d7080 ctr  0x0
link 0x100d705c xer  0x0
ccr  0x54428882 trap 0xc00
JeremyRand commented 2 years ago

Any luck analyzing the dump?

nmeum commented 2 years ago

I've been also getting a lot of spurious timed out waiting for a requested PING response errors with current git HEAD lately that I didn't get before. Not sure if this is related but might be a regression introduced in 887ab30b9028c8c8f178aa73dcac50366a681052?

lrstanley commented 2 years ago

I've been also getting a lot of spurious timed out waiting for a requested PING response errors with current git HEAD lately that I didn't get before. Not sure if this is related but might be a regression introduced in 887ab30?

How much is a lot? Any info/logs for reproduction?

lrstanley commented 2 years ago

Any luck analyzing the dump?

Sorry for the delay -- taking a look now.

lrstanley commented 2 years ago

I've pushed https://github.com/lrstanley/girc/commit/da08de25b4527e50247dc3f8afd589c73b5e0634 to branch bugfix/issue-50, with what I think is a sufficient enough fix, however it's not very clean, and I haven't extensively tested it.

girc was initially released a few months after context.Context was added to the standard library. As such, my original adoption was very limited (and I really wish I had rewritten to support it more). Much of the core functionality isn't the most idiomatic Go due to that, and me not using channels properly back then.

I'd update to be more idiomatic, however it'd break the API, and frankly, it'd be a lot of work. So here is to hoping this fix works. 😄

lrstanley commented 2 years ago

Another item -- from that goroutine dump, looks like there are a lot of handlers inside of matterbridge which are waiting to send data to some channel inside of matterbridge itself. I am not sure if that's directly related to this issue, or a cause for another issue. Non-background handlers registered with girc will cause girc to block until they've completed, including waiting for the client to close, whereas background handlers are fire and forget.

JeremyRand commented 2 years ago

@42wim Any chance you could create a Matterbridge branch with the proposed fix? Would make it easier for me to test.

lrstanley commented 1 year ago

I have merged the functionality in bugfix/issue-50 into master. Since I haven't heard back in some time, will close out. Can re-open if needed though.