Error in the server sish log

[manprint]

Hi @antoniomika,

Checking sish server logs, sometimes I get this error:

2022/11/19 14:28:38 [Recovery] 2022/11/19 - 14:28:38 panic recovered:
net/http: abort Handler
/usr/local/go/src/net/http/httputil/reverseproxy.go:363 (0x99e708)
/go/pkg/mod/github.com/antoniomika/oxy@v1.1.1-0.20210804032133-5924ea01c950/forward/fwd.go:540 (0x9fddcb)
/go/pkg/mod/github.com/antoniomika/oxy@v1.1.1-0.20210804032133-5924ea01c950/forward/fwd.go:267 (0x9face6)
/go/pkg/mod/github.com/antoniomika/oxy@v1.1.1-0.20210804032133-5924ea01c950/roundrobin/rr.go:147 (0x9f61a7)
/go/pkg/mod/github.com/gin-gonic/gin@v1.8.1/utils.go:49 (0x9b5e08)
/app/httpmuxer/httpmuxer.go:311 (0xaec203)
/go/pkg/mod/github.com/gin-gonic/gin@v1.8.1/context.go:173 (0x9aefa1)
/go/pkg/mod/github.com/gin-gonic/gin@v1.8.1/recovery.go:101 (0x9aef8c)
/go/pkg/mod/github.com/gin-gonic/gin@v1.8.1/context.go:173 (0x9ae0a6)
/go/pkg/mod/github.com/gin-gonic/gin@v1.8.1/logger.go:240 (0x9ae089)
/go/pkg/mod/github.com/gin-gonic/gin@v1.8.1/context.go:173 (0xaecdde)
/app/httpmuxer/httpmuxer.go:71 (0xaecc47)
/go/pkg/mod/github.com/gin-gonic/gin@v1.8.1/context.go:173 (0x9ad24c)
/go/pkg/mod/github.com/gin-gonic/gin@v1.8.1/gin.go:652 (0x9ad235)
/go/pkg/mod/github.com/gin-gonic/gin@v1.8.1/gin.go:645 (0x9acf84)
/go/pkg/mod/github.com/gin-gonic/gin@v1.8.1/gin.go:572 (0x9ac91c)
/go/pkg/mod/github.com/caddyserver/certmagic@v0.17.2/httphandler.go:36 (0xabaab6)
/usr/local/go/src/net/http/server.go:2109 (0x75258e)
/usr/local/go/src/net/http/server.go:2947 (0x755e4b)
/usr/local/go/src/net/http/server.go:1991 (0x751066)
/usr/local/go/src/runtime/asm_amd64.s:1594 (0x466f40)

I'm using a lot of sish for development. Functionally, I didn't notice any issue. I couldn't figure out exactly when this error occurs.

I'll send you the error message anyway, maybe there's something I'm doing wrong as a configuration or there's some check that can be done in the server code.

Thank you. Have a nice weekend.

[manprint]

I've turned on debugging. I am attaching additional log files with debugging and sish server configurations

debug_log.txt

debug_log_1.txt

start_sish_script.txt

apache2_config.txt

I hope they can be useful to you

Thanks.

[manprint]

Hi Antonio,

I was able to reproduce the case where this error occurs.

Panic error occurs when accessing files in webdav server

In particular, when I access some file (for example "griffin1x01.mp4" (PS: I like griffins :D )) the error is shown in the logs.

I am attaching the complete log file with all the calls that are made to the server.

issue_full_log.txt

If you want me to test the fix, publish the docker image with it. I'll be happy to check it out.

Thank you. Fabio

[antoniomika]

Hey @manprint,

Does this actually cause an issue for you? Kinda looks like a delayed error that shouldn't really cause a problem.

Best,

[manprint]

Hi @antoniomika Thanks for the reply!!!

Functionally the error doesn't cause me problems. Sish works fine!

I'll explain why I opened the issue.

My team works a lot with small video clips and we use webdav servers. Sish helps us a lot to do tests. I noticed that over time the system logs (normal, not debugged) grew in size very quickly. Looking at the logs I found the error repeated countless times working with these video files. While doing some tests (with griffin file :D) I saw that it happens when these video files are accessed via webdav via sish. Thats all.

Maybe something could be done to catch the error and show a warning instead of the whole error panic stack? So the logs are cleaner.

What do you think about it?

Thanks. Fabio

[antoniomika]

I appreciate it! I think the issue is a context deadline is being hit when streaming the data.

Did you try disabling idle connection checking (i.e. --idle-connection=false)?

Essentially, this sets the connection timeout for reads/writes. My guess is that's actually prematurely killing HTTP streaming connections.

Try it out and let me know!

[manprint]

Hi @antoniomika As always, thanks for the reply.

I tried with version 2.9.2 with the following run:

docker run -itd --name sish \
        -v $(pwd)/keys:/keys \
        -v $(pwd)/pubkeys:/pubkeys \
        --restart=always \
        -p 2222:2222 \
        -p 4443:4443 \
        -p 8765:80 \
        --log-driver=json-file \
        --log-opt max-size=5m \
        --log-opt max-file=2 \
        --log-opt compress=true \
        antoniomika/sish:v2.9.2 \
        --ssh-address=:2222 \
        --http-address=:80 \
        --https=true \
        --authentication-keys-directory=/pubkeys \
        --private-keys-directory=/keys \
        --tcp-aliases \
        --bind-random-aliases=false \
        --bind-random-ports=false \
        --bind-random-subdomains=false \
        --authentication-password= \
        --domain=apps.internaltest.tk \
        --idle-connection=false \
        --admin-console \
        --admin-console-token=mysecrettoken \
        --verify-ssl=false \
        --service-console-max-content-length=0

Unfortunately with the --idle-connection=false option the error is still there.

I saw the line of code that gives the error. It is an error generated in the go reverseproxy library (reverseproxy.go:363). It's not a sish issue.

err = p.copyResponse(rw, res.Body, p.flushInterval(res))
    if err != nil {
        defer res.Body.Close()
        // Since we're streaming the response, if we run into an error all we can do
        // is abort the request. Issue 23643: ReverseProxy should use ErrAbortHandler
        // on read error while copying body.
        if !shouldPanicOnCopyError(req) {
            p.logf("suppressing panic for copyResponse error in test; copy error: %v", err)
            return
        }
        panic(http.ErrAbortHandler)
    }
    res.Body.Close() // close now, instead of defer, to populate res.Trailer

At this point, since for me the error is not blocking, if you believe that in other use cases it does not generate problems, you can close the issue.

For the issue of growing logs, I can safely put limits like --log-opt max-size=5m in the docker run.

Thank you so much and I wish you a merry Christmas.

Best, Fabio

[antoniomika]

Appreciate it @manprint! Gonna close for now as it's not a blocking issue. If we starting having more problems with it, we can look into it again.

Merry christmas and happy holidays as well!