search

OpenPrinting / ipp-usb

ipp-usb -- HTTP reverse proxy, backed by IPP-over-USB connection to device
BSD 2-Clause "Simplified" License
129 stars 11 forks source link

Spurious panic on USB device removal #19

Closed fabled closed 3 years ago

fabled commented 3 years ago 
- HOTPLUG: removed Bus 001 Device 009
  USB[0]: open: Bus 001 Device 009 Interface 0 Alt 1
! USB[0]: libusb_claim_interface: No such device (it may have been disconnected)
! PNP Bus 001 Device 009: libusb_claim_interface: No such device (it may have been disconnected)
- PNP Bus 001 Device 008: removed
fatal error: unexpected signal during runtime execution
[signal SIGSEGV: segmentation violation code=0x80 addr=0x0 pc=0x7f5703046bae]

runtime stack:
runtime.throw(0x765893, 0x2a)
    /usr/lib/go/src/runtime/panic.go:1116 +0x72
runtime.sigpanic()
    /usr/lib/go/src/runtime/signal_unix.go:726 +0x4ac

goroutine 1 [syscall]:
runtime.cgocall(0x6c3b90, 0xc0001632c0, 0x6b8000)
    /usr/lib/go/src/runtime/cgocall.go:133 +0x5b fp=0xc000163290 sp=0xc000163258 pc=0x40715b
main._Cfunc_avahi_entry_group_free(0x7f56dbeed550, 0xc000000000)
    _cgo_gotypes.go:420 +0x49 fp=0xc0001632c0 sp=0xc000163290 pc=0x6b7c09
main.(*dnssdSysdep).destroy.func1(0xc0001a8680, 0xc000163310)
    /home/tteras/oss/ipp-usb/dnssd_avahi.go:230 +0x5a fp=0xc0001632f8 sp=0xc0001632c0 pc=0x6bf81a
main.(*dnssdSysdep).destroy(0xc0001a8680)
    /home/tteras/oss/ipp-usb/dnssd_avahi.go:230 +0xaf fp=0xc000163320 sp=0xc0001632f8 pc=0x6bb1cf
main.(*dnssdSysdep).Close(0xc0001a8680)
    /home/tteras/oss/ipp-usb/dnssd_avahi.go:215 +0x33 fp=0xc000163338 sp=0xc000163320 pc=0x6bb0f3
main.(*DNSSdPublisher).Unpublish(0xc000230500)
    /home/tteras/oss/ipp-usb/dnssd.go:165 +0x57 fp=0xc0001633a8 sp=0xc000163338 pc=0x69bbd7
main.(*Device).Close(0xc0001a85c0)
    /home/tteras/oss/ipp-usb/device.go:198 +0xf3 fp=0xc0001633d8 sp=0xc0001633a8 pc=0x69a713
main.PnPStart(0x7f5702ff2200, 0x0)
    /home/tteras/oss/ipp-usb/pnp.go:88 +0x1371 fp=0xc000163b70 sp=0xc0001633d8 pc=0x6aed71
main.main()
    /home/tteras/oss/ipp-usb/main.go:244 +0x52c fp=0xc000163f88 sp=0xc000163b70 pc=0x6ac6cc
runtime.main()
    /usr/lib/go/src/runtime/proc.go:204 +0x209 fp=0xc000163fe0 sp=0xc000163f88 pc=0x43ba09
runtime.goexit()
    /usr/lib/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc000163fe8 sp=0xc000163fe0 pc=0x46dde1

goroutine 6 [syscall]:
main._Cfunc_libusb_handle_events(0x7f5702ff22b0, 0xc000000000)
    _cgo_gotypes.go:838 +0x49
main.libusbContext.func3.1(0x0)
    /home/tteras/oss/ipp-usb/usbio_libusb.go:132 +0x58
main.libusbContext.func3()
    /home/tteras/oss/ipp-usb/usbio_libusb.go:132 +0x25
created by main.libusbContext
    /home/tteras/oss/ipp-usb/usbio_libusb.go:129 +0x136

goroutine 18 [syscall, 66 minutes]:
os/signal.signal_recv(0x0)
    /usr/lib/go/src/runtime/sigqueue.go:147 +0x9d
os/signal.loop()
    /usr/lib/go/src/os/signal/signal_unix.go:23 +0x25
created by os/signal.Notify.func1.1
    /usr/lib/go/src/os/signal/signal.go:150 +0x45

goroutine 309 [IO wait]:
internal/poll.runtime_pollWait(0x7f56dc1a7dd0, 0x72, 0x0)
    /usr/lib/go/src/runtime/netpoll.go:222 +0x55
internal/poll.(*pollDesc).wait(0xc00015a418, 0x72, 0x0, 0x0, 0x756b06)
    /usr/lib/go/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
    /usr/lib/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Accept(0xc00015a400, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
    /usr/lib/go/src/internal/poll/fd_unix.go:394 +0x1fc
net.(*netFD).accept(0xc00015a400, 0xc000230460, 0x50, 0x50)
    /usr/lib/go/src/net/fd_unix.go:172 +0x45
net.(*TCPListener).accept(0xc0001ee2a0, 0x30, 0x72f900, 0xc000230460)
    /usr/lib/go/src/net/tcpsock_posix.go:139 +0x32
net.(*TCPListener).Accept(0xc0001ee2a0, 0xc00032afc0, 0x411818, 0xc000580000, 0x0)
    /usr/lib/go/src/net/tcpsock.go:261 +0x65
main.Listener.Accept(0x7c0fc0, 0xc0001ee2a0, 0x411818, 0x30, 0x72f900, 0xc000014201)
    /home/tteras/oss/ipp-usb/listener.go:56 +0x35
net/http.(*Server).Serve(0xc0000141c0, 0x7c1300, 0xc0000fc440, 0x0, 0x0)
    /usr/lib/go/src/net/http/server.go:2937 +0x266
main.NewHTTPProxy.func1(0xc0002f8c60, 0x7c1300, 0xc0000fc440)
    /home/tteras/oss/ipp-usb/http.go:55 +0x45
created by main.NewHTTPProxy
    /home/tteras/oss/ipp-usb/http.go:54 +0x16b
alexpevzner commented 3 years ago

20 seems to be duplicate of this issue

alexpevzner commented 3 years ago

I've blindly fixed the problem. Could you please retest and confirm that the fix works?

fabled commented 3 years ago

Seems the same test case does not immediately cause issues anymore. So likely fixed. Thanks for the quick fix!

alexpevzner commented 3 years ago

I'll close this bug just after the next release. Please, keep it open for now.

fabled commented 3 years ago

New panic running git revision 5f743231ae0e09807d15f68a92a174bda41f29aa when AVAHI not running but device is connected:

> HP Color LaserJet FlowMFP M578 [7839F2]: _http._tcp TXT record:
  DNS-SD: HP Color LaserJet FlowMFP M578 [7839F2] (USB): trying
  DNS-SD: FQDN: ""
- Bus 001 Device 004: resetting HP Color LaserJet FlowMFP M578
  USB[0]: closed
  USB[1]: closed
  USB[2]: closed
  USB[3]: closed
- Bus 001 Device 004: removed HP Color LaserJet FlowMFP M578
! PNP Bus 001 Device 004: AVAHI: Bad state
fatal error: unexpected signal during runtime execution
[signal SIGSEGV: segmentation violation code=0x80 addr=0x0 pc=0x7f9a814553db]

runtime stack:
runtime.throw(0x765893, 0x2a)
    /usr/lib/go/src/runtime/panic.go:1116 +0x72
runtime.sigpanic()
    /usr/lib/go/src/runtime/signal_unix.go:726 +0x4ac

goroutine 34 [syscall]:
runtime.cgocall(0x6c3e00, 0xc00004ab50, 0xc0002e9c00)
    /usr/lib/go/src/runtime/cgocall.go:133 +0x5b fp=0xc00004ab20 sp=0xc00004aae8 pc=0x40715b
main._Cfunc_libusb_bulk_transfer(0x7f9a81464c00, 0xc000410182, 0xc000388000, 0x2000, 0xc000410168, 0x0, 0x0)
    _cgo_gotypes.go:606 +0x4d fp=0xc00004ab50 sp=0xc00004ab20 pc=0x6b850d
main.(*UsbInterface).Recv.func1(0xc000198680, 0xc000388000, 0x2000, 0x2000, 0xc000410168, 0x0, 0x7721d0)
    /home/tteras/oss/ipp-usb/usbio_libusb.go:638 +0xc5 fp=0xc00004aba8 sp=0xc00004ab50 pc=0x6c14a5
main.(*UsbInterface).Recv(0xc000198680, 0xc000388000, 0x2000, 0x2000, 0x0, 0xc00004ac90, 0x1, 0x1)
    /home/tteras/oss/ipp-usb/usbio_libusb.go:638 +0x8f fp=0xc00004ac18 sp=0xc00004aba8 pc=0x6be6cf
main.(*usbConn).Read(0xc00019a720, 0xc000388000, 0x2000, 0x2000, 0x0, 0x0, 0x0)
    /home/tteras/oss/ipp-usb/usbtransport.go:595 +0x227 fp=0xc00004ad28 sp=0xc00004ac18 pc=0x6b5c07
bufio.(*Reader).Read(0xc00018eae0, 0xc000388000, 0x2000, 0x2000, 0xc000038dd8, 0x941100, 0xc000038e60)
    /usr/lib/go/src/bufio/bufio.go:213 +0x142 fp=0xc00004ad78 sp=0xc00004ad28 pc=0x567f02
net/http.(*body).readLocked(0xc00021a0c0, 0xc000388000, 0x2000, 0x2000, 0x92dfe0, 0xc000180800, 0x0)
    /usr/lib/go/src/net/http/transfer.go:833 +0x5f fp=0xc00004add8 sp=0xc00004ad78 pc=0x66333f
net/http.(*body).Read(0xc00021a0c0, 0xc000388000, 0x2000, 0x2000, 0x0, 0x0, 0x0)
    /usr/lib/go/src/net/http/transfer.go:825 +0xf9 fp=0xc00004ae40 sp=0xc00004add8 pc=0x663259
io/ioutil.devNull.ReadFrom(0x0, 0x7f9a5a64e698, 0xc00021a0c0, 0x706780, 0x72cb01, 0x7f9a5a529ba0)
    /usr/lib/go/src/io/ioutil/ioutil.go:144 +0x92 fp=0xc00004aeb0 sp=0xc00004ae40 pc=0x5846b2
io/ioutil.(*devNull).ReadFrom(0x9a1f80, 0x7f9a5a64e698, 0xc00021a0c0, 0x7f9a5a529ba0, 0x9a1f80, 0x1)
    <autogenerated>:1 +0x50 fp=0xc00004aef0 sp=0xc00004aeb0 pc=0x584d10
io.copyBuffer(0x7bc520, 0x9a1f80, 0x7f9a5a64e698, 0xc00021a0c0, 0x0, 0x0, 0x0, 0xc00019e090, 0x0, 0x0)
    /usr/lib/go/src/io/io.go:395 +0x2ff fp=0xc00004af68 sp=0xc00004aef0 pc=0x4a24df
io.Copy(...)
    /usr/lib/go/src/io/io.go:368
main.(*usbResponseBodyWrapper).Close.func1(0xc00021a100)
    /home/tteras/oss/ipp-usb/usbtransport.go:491 +0xab fp=0xc00004afd8 sp=0xc00004af68 pc=0x6bf06b
runtime.goexit()
    /usr/lib/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc00004afe0 sp=0xc00004afd8 pc=0x46dde1
created by main.(*usbResponseBodyWrapper).Close
    /home/tteras/oss/ipp-usb/usbtransport.go:483 +0xc7

goroutine 1 [select]:
main.PnPStart(0x7f9a81483200, 0x0)
    /home/tteras/oss/ipp-usb/pnp.go:127 +0x3b1
main.main()
    /home/tteras/oss/ipp-usb/main.go:244 +0x52c

goroutine 6 [syscall]:
main._Cfunc_libusb_handle_events(0x7f9a814832b0, 0xc000000000)
    _cgo_gotypes.go:838 +0x49
main.libusbContext.func3.1(0x0)
    /home/tteras/oss/ipp-usb/usbio_libusb.go:132 +0x58
main.libusbContext.func3()
    /home/tteras/oss/ipp-usb/usbio_libusb.go:132 +0x25
created by main.libusbContext
    /home/tteras/oss/ipp-usb/usbio_libusb.go:129 +0x136

goroutine 8 [syscall]:
os/signal.signal_recv(0x0)
    /usr/lib/go/src/runtime/sigqueue.go:147 +0x9d
os/signal.loop()
    /usr/lib/go/src/os/signal/signal_unix.go:23 +0x25
created by os/signal.Notify.func1.1
    /usr/lib/go/src/os/signal/signal.go:150 +0x45
fabled commented 3 years ago

Another crash when AVAHI is stopped duing ipp-usb runtime:

! DNS-SD: HP Color LaserJet FlowMFP M578 [7839F2] (USB): AVAHI: Bad state
! panic: runtime error: invalid memory address or nil pointer dereference
!
! goroutine 39 [running]:
! runtime/debug.Stack(0xc00010eaa0, 0x1, 0x481e21)
!   /usr/lib/go/src/runtime/debug/stack.go:24 +0x9f
! main.(*Logger).Panic(0xc00010eaa0, 0x6ff160, 0x92cbf0)
!   /home/tteras/oss/ipp-usb/logger.go:233 +0xf4
! main.(*DNSSdPublisher).goroutine.func1()
!   /home/tteras/oss/ipp-usb/dnssd.go:204 +0x4d
! panic(0x6ff160, 0x92cbf0)
!   /usr/lib/go/src/runtime/panic.go:969 +0x1b9
! main.(*dnssdSysdep).Chan(...)
!   /home/tteras/oss/ipp-usb/dnssd_avahi.go:225
! main.(*DNSSdPublisher).goroutine(0xc0001a65a0)
!   /home/tteras/oss/ipp-usb/dnssd.go:225 +0x14d
! created by main.(*DNSSdPublisher).Publish
!   /home/tteras/oss/ipp-usb/dnssd.go:155 +0x1a5
alexpevzner commented 3 years ago

Got it, will investigate.

You also promised to test latest sane-airscan changes against HP Color LaserJet FlowMFP M578...

fabled commented 3 years ago

You also promised to test latest sane-airscan changes against HP Color LaserJet FlowMFP M578...

Yes, so far all features work as expected. No issues with multi page duplex ADF jobs, nor flatbed. But I created https://github.com/alexpevzner/sane-airscan/issues/116 to request making this quirk handling more generic.

alexpevzner commented 3 years ago

Hi!

I believe, I've fixed all issues (spurious panic and #22). Please, retest.

alexpevzner commented 3 years ago

Ping

fabled commented 3 years ago

I had time for quick test only. The avani not running related panic that was reproducible is fixed. Thank you!

I had quite limited time to test, so I am not fully certain of the other panic's status. However, no panic so far. So looking good.

alexpevzner commented 3 years ago

Fixed in 0.9.17