Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closing of websocket by remote server does not trigger the script close handler #581

Closed
na-- opened this issue Apr 12, 2018 · 4 comments · Fixed by #1186
Closed

Closing of websocket by remote server does not trigger the script close handler #581

na-- opened this issue Apr 12, 2018 · 4 comments · Fixed by #1186

Comments

@na--
Copy link
Member

na-- commented Apr 12, 2018

When the remote server closes the websocket like this, the close handler in the script is not called and the script iteration never finishes executing, it becomes stuck in the websocket handling code.

The error handler is called with an error like GoError: An unexpected error occured: websocket: close 1006 (abnormal closure): unexpected EOF...., which is probably also suboptimal.

@na-- na-- added the bug label Apr 12, 2018
@na-- na-- changed the title Closing of websocket by remote server hangs script and does not trigger the close WS handler Closing of websocket by remote server does not trigger the script close handler Apr 12, 2018
@jonathandemoor
Copy link

Any updates? 😅

@na--
Copy link
Member Author

na-- commented Feb 13, 2019

@jonathandemoor unfortunately not at this time, sorry...

@mstoykov
Copy link
Contributor

mstoykov commented Mar 1, 2019

On related note I just got a panic in the ws test:

ok      github.com/loadimpact/k6/js/modules/k6/metrics  4.385s
panic: runtime error: invalid memory address or nil pointer dereference [recovered]
        panic: Panic at 4: runtime error: invalid memory address or nil pointer dereference [recovered]
        panic: Panic at 4: runtime error: invalid memory address or nil pointer dereference [recovered]
        panic: Panic at 7: Panic at 4: runtime error: invalid memory address or nil pointer dereference [recovered]
        panic: Panic at 7: Panic at 4: runtime error: invalid memory address or nil pointer dereference [recovered]
        panic: Panic at 7: Panic at 4: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x83cb53]

goroutine 6 [running]:
testing.tRunner.func1(0xc000132900)
        /home/mstoykov/.gvm/gos/go1.11.1/src/testing/testing.go:792 +0x387
panic(0x99bbc0, 0xc000a906f0)
        /home/mstoykov/.gvm/gos/go1.11.1/src/runtime/panic.go:513 +0x1b9
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*Runtime).RunProgram.func1(0xc003085e10)
        /home/mstoykov/.gvm/pkgsets/go1.11.1/global/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/runtime.go:880 +0x9b
panic(0x99bbc0, 0xc000a906f0)
        /home/mstoykov/.gvm/gos/go1.11.1/src/runtime/panic.go:513 +0x1b9
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*vm).try.func1(0xc0001daa90, 0x0, 0xc003085d10, 0x0, 0x0, 0x0, 0xc003085d68)
        /home/mstoykov/.gvm/pkgsets/go1.11.1/global/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/vm.go:364 +0x459
panic(0x99bbc0, 0xc000a906e0)
        /home/mstoykov/.gvm/gos/go1.11.1/src/runtime/panic.go:513 +0x1b9
github.com/loadimpact/k6/vendor/github.com/dop251/goja.AssertFunction.func1.1(0xc003084f80)
        /home/mstoykov/.gvm/pkgsets/go1.11.1/global/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/runtime.go:1407 +0x9b
panic(0x99bbc0, 0xc000a906e0)
        /home/mstoykov/.gvm/gos/go1.11.1/src/runtime/panic.go:513 +0x1b9
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*vm).try.func1(0xc0001daa90, 0x1, 0xc003084e88, 0x4, 0x0, 0x1, 0xc003084ee0)
        /home/mstoykov/.gvm/pkgsets/go1.11.1/global/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/vm.go:364 +0x459
panic(0x9a9640, 0x1139e60)
        /home/mstoykov/.gvm/gos/go1.11.1/src/runtime/panic.go:513 +0x1b9
github.com/loadimpact/k6/vendor/github.com/gorilla/websocket.(*Conn).WriteControl(0x0, 0x8, 0xc00089e158, 0x2, 0x2, 0xbf16569b8b8a907a, 0x463dda2b8, 0x114c640, 0x0, 0x0)
        /home/mstoykov/.gvm/pkgsets/go1.11.1/global/src/github.com/loadimpact/k6/vendor/github.com/gorilla/websocket/conn.go:412 +0x73
github.com/loadimpact/k6/js/modules/k6/ws.(*Socket).closeConnection.func1()
        /home/mstoykov/.gvm/pkgsets/go1.11.1/global/src/github.com/loadimpact/k6/js/modules/k6/ws/ws.go:434 +0x16d
sync.(*Once).Do(0xc0004e2170, 0xc003084550)
        /home/mstoykov/.gvm/gos/go1.11.1/src/sync/once.go:44 +0xb3
github.com/loadimpact/k6/js/modules/k6/ws.(*Socket).closeConnection(0xc0004e2140, 0x3e9, 0x465eb6, 0x973b40)
        /home/mstoykov/.gvm/pkgsets/go1.11.1/global/src/github.com/loadimpact/k6/js/modules/k6/ws/ws.go:431 +0x76
github.com/loadimpact/k6/js/modules/k6/ws.(*Socket).Close(0xc0004e2140, 0x116afc0, 0x0, 0x0)
        /home/mstoykov/.gvm/pkgsets/go1.11.1/global/src/github.com/loadimpact/k6/js/modules/k6/ws/ws.go:424 +0x3f
reflect.callMethod(0xc0021720c0, 0xc0030846b0, 0xc003084698)
        /home/mstoykov/.gvm/gos/go1.11.1/src/reflect/value.go:689 +0x180
reflect.methodValueCall(0x116afc0, 0x0, 0x0, 0xc0014e6580, 0xc003084998, 0x4b4db9, 0xc000fa24e0, 0xc0021720c0, 0xc0014e65c0, 0x1800000018, ...)
        /home/mstoykov/.gvm/gos/go1.11.1/src/reflect/asm_amd64.s:35 +0x42
reflect.Value.call(0x971880, 0xc0021720c0, 0x13, 0xa52844, 0x4, 0x116afc0, 0x1, 0x0, 0xa50020, 0x1, ...)
        /home/mstoykov/.gvm/gos/go1.11.1/src/reflect/value.go:447 +0x449
reflect.Value.Call(0x971880, 0xc0021720c0, 0x13, 0x116afc0, 0x0, 0x0, 0x203000, 0x203000, 0xc0014e6540)
        /home/mstoykov/.gvm/gos/go1.11.1/src/reflect/value.go:308 +0xa4
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*Runtime).wrapReflectFunc.func1(0xbb8420, 0xc0014e61c0, 0xc0004e8090, 0x0, 0x5, 0xc0004e80e0, 0x2)
        /home/mstoykov/.gvm/pkgsets/go1.11.1/global/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/runtime.go:1153 +0x7c3
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*vm)._nativeCall(0xc0001daa90, 0xc0004e4210, 0x0)
        /home/mstoykov/.gvm/pkgsets/go1.11.1/global/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/vm.go:1826 +0x284
github.com/loadimpact/k6/vendor/github.com/dop251/goja.call.exec(0x0, 0xc0001daa90)
        /home/mstoykov/.gvm/pkgsets/go1.11.1/global/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/vm.go:1810 +0x4e3
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*vm).run(0xc0001daa90)
        /home/mstoykov/.gvm/pkgsets/go1.11.1/global/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/vm.go:288 +0x5d
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*funcObject).Call(0xc000bd6480, 0xbb8b00, 0x116ad20, 0xc000a90500, 0x1, 0x1, 0xc003084dd8, 0x40beb3)
        /home/mstoykov/.gvm/pkgsets/go1.11.1/global/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/func.go:130 +0x2be
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*funcObject).Call-fm(0xbb8b00, 0x116ad20, 0xc000a90500, 0x1, 0x1, 0xa07200, 0xc0004e2140)
        /home/mstoykov/.gvm/pkgsets/go1.11.1/global/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/builtin_function.go:120 +0x48
github.com/loadimpact/k6/vendor/github.com/dop251/goja.AssertFunction.func1.2()
        /home/mstoykov/.gvm/pkgsets/go1.11.1/global/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/runtime.go:1412 +0x96
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*vm).try(0xc0001daa90, 0xc003084ef8, 0x0)
        /home/mstoykov/.gvm/pkgsets/go1.11.1/global/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/vm.go:370 +0x10c
github.com/loadimpact/k6/vendor/github.com/dop251/goja.AssertFunction.func1(0xbb8b00, 0x116ad20, 0xc000a90500, 0x1, 0x1, 0x0, 0x0, 0x0, 0x0)
        /home/mstoykov/.gvm/pkgsets/go1.11.1/global/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/runtime.go:1411 +0x10d
github.com/loadimpact/k6/js/modules/k6/ws.(*WS).Connect(0x116afc0, 0xbb3da0, 0xc000209e60, 0xc00107e6a4, 0x1b, 0xc000a8ea30, 0x1, 0x1, 0x0, 0x0, ...)
        /home/mstoykov/.gvm/pkgsets/go1.11.1/global/src/github.com/loadimpact/k6/js/modules/k6/ws/ws.go:196 +0x70f
reflect.Value.call(0x99bc20, 0x116afc0, 0x213, 0xa5489c, 0x9, 0xc000bdc410, 0x3, 0x3, 0xa0eac0, 0xc000a8ea40, ...)
        /home/mstoykov/.gvm/gos/go1.11.1/src/reflect/value.go:447 +0x449
reflect.Value.CallSlice(0x99bc20, 0x116afc0, 0x213, 0xc000bdc410, 0x3, 0x3, 0x194, 0x8, 0xc0030859c8)
        /home/mstoykov/.gvm/gos/go1.11.1/src/reflect/value.go:321 +0xa4
github.com/loadimpact/k6/js/common.Bind.func1(0xbb8420, 0xc00020afc0, 0xc000c389e0, 0x2, 0x4, 0xc0021887c0, 0x0)
        /home/mstoykov/.gvm/pkgsets/go1.11.1/global/src/github.com/loadimpact/k6/js/common/bridge.go:237 +0xa23
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*vm)._nativeCall(0xc0001daa90, 0xc000bd2f20, 0x2)
        /home/mstoykov/.gvm/pkgsets/go1.11.1/global/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/vm.go:1826 +0x284
github.com/loadimpact/k6/vendor/github.com/dop251/goja.call.exec(0x2, 0xc0001daa90)
        /home/mstoykov/.gvm/pkgsets/go1.11.1/global/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/vm.go:1810 +0x4e3
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*vm).run(0xc0001daa90)
        /home/mstoykov/.gvm/pkgsets/go1.11.1/global/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/vm.go:288 +0x5d
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*vm).run-fm()
        /home/mstoykov/.gvm/pkgsets/go1.11.1/global/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/vm.go:375 +0x2a
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*vm).try(0xc0001daa90, 0xc003085d70, 0x0)
        /home/mstoykov/.gvm/pkgsets/go1.11.1/global/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/vm.go:370 +0x10c
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*vm).runTry(0xc0001daa90, 0xb376d0)
        /home/mstoykov/.gvm/pkgsets/go1.11.1/global/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/vm.go:375 +0x4e
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*Runtime).RunProgram(0xc000001b00, 0xc000c388a0, 0x0, 0x0, 0x0, 0x0)
        /home/mstoykov/.gvm/pkgsets/go1.11.1/global/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/runtime.go:891 +0x1b7
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*Runtime).RunScript(0xc000001b00, 0x0, 0x0, 0xc00107e4e0, 0xc4, 0x0, 0x8000106, 0x0, 0xffffffffffffffff)
        /home/mstoykov/.gvm/pkgsets/go1.11.1/global/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/runtime.go:870 +0x9b
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*Runtime).RunString(0xc000001b00, 0xc00107e4e0, 0xc4, 0xa5559a, 0xa, 0xc00107e4e0, 0xc4)
        /home/mstoykov/.gvm/pkgsets/go1.11.1/global/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/runtime.go:859 +0x47
github.com/loadimpact/k6/js/common.RunString(0xc000001b00, 0xa6f074, 0xc1, 0xc000052798, 0x47cb36, 0x5c78e2db, 0x14b40b0b)
        /home/mstoykov/.gvm/pkgsets/go1.11.1/global/src/github.com/loadimpact/k6/js/common/util.go:39 +0xf3
github.com/loadimpact/k6/js/modules/k6/ws.TestSession.func1(0xc000132900)
        /home/mstoykov/.gvm/pkgsets/go1.11.1/global/src/github.com/loadimpact/k6/js/modules/k6/ws/ws_test.go:122 +0x3f
testing.tRunner(0xc000132900, 0xc000201240)
        /home/mstoykov/.gvm/gos/go1.11.1/src/testing/testing.go:827 +0xbf
created by testing.(*T).Run
        /home/mstoykov/.gvm/gos/go1.11.1/src/testing/testing.go:878 +0x353
FAIL    github.com/loadimpact/k6/js/modules/k6/ws       8.876s

This has never happened before and I do a lot of test runs :) I can't at the moment look into it but it might be relevant

@imiric
Copy link
Contributor

imiric commented Oct 3, 2019

We already have a WS close test that checks if the close handler is called, but it initiates the close from the client side, so it doesn't reproduce this issue.

It seems that k6 is not properly handling a server-initiated close. Will look into this.

@imiric imiric self-assigned this Oct 3, 2019
imiric pushed a commit that referenced this issue Oct 4, 2019
This avoids a hanging behavior when the server closes the WS connection,
either via a control close frame[1] or by closing the connection
prematurely without sending the control frame (deviating from the WS
protocol).

If the control close frame is not received but the connection is closed,
the error (`close 1006 (abnormal closure): unexpected EOF`) will be
returned to the user's WS error handler, as it indicates an issue with
the server.

The user-specified close handler should be called in either case now.

Closes #581

[1]: https://tools.ietf.org/html/rfc6455#section-5.5.1
imiric pushed a commit that referenced this issue Oct 23, 2019
This avoids a hanging behavior when the server closes the WS connection,
either via a control close frame[1] or by closing the connection
prematurely without sending the control frame (deviating from the WS
protocol).

If the control close frame is not received but the connection is closed,
the error (`close 1006 (abnormal closure): unexpected EOF`) will be
returned to the user's WS error handler, as it indicates an issue with
the server.

The user-specified close handler should be called in either case now.

Closes #581

[1]: https://tools.ietf.org/html/rfc6455#section-5.5.1
imiric pushed a commit that referenced this issue Oct 25, 2019
This avoids a hanging behavior when the server closes the WS connection,
either via a control close frame[1] or by closing the connection
prematurely without sending the control frame (deviating from the WS
protocol).

If the control close frame is not received but the connection is closed,
the error (`close 1006 (abnormal closure): unexpected EOF`) will be
returned to the user's WS error handler, as it indicates an issue with
the server.

The user-specified close handler should be called in either case now.

This required rewriting the test httpmultibin WS server handlers, since
the previous ones don't comply with the WS spec. New test code shouldn't
use the `*-invalid` endpoints, which are there only for compatibility
with existing tests, which should be rewritten soon.

Closes #581

[1]: https://tools.ietf.org/html/rfc6455#section-5.5.1
imiric pushed a commit that referenced this issue Oct 28, 2019
This avoids a hanging behavior when the server closes the WS connection,
either via a control close frame[1] or by closing the connection
prematurely without sending the control frame (deviating from the WS
protocol).

If the control close frame is not received but the connection is closed,
the error (`close 1006 (abnormal closure): unexpected EOF`) will be
returned to the user's WS error handler, as it indicates an issue with
the server.

The user-specified close handler should be called in either case now.

This required rewriting the test httpmultibin WS server handlers, since
the previous ones don't comply with the WS spec. New test code shouldn't
use the `*-invalid` endpoints, which are there only for compatibility
with existing tests, which should be rewritten soon.

Closes #581

[1]: https://tools.ietf.org/html/rfc6455#section-5.5.1
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants