Windows Error

[enochtsang]

From windows sending to a unix syslog server, the syslog server still receives the messages but also gets the error:

rsyslogd-2165: netstream session 0x7f2ca00067e0 will be closed due to error
 [try http://www.rsyslog.com/e/2165 ]

[nathanaelle]

I don't understand your issue … do have an issue with MS Windows that forwards to a rsyslog server on a Unix-like system ?

the error message you reported is about your rsyslog collector not my go library, and is issued by rsyslog.

If you use my go library on your MS Windows client, can you explain with more details, how the issue happen ?

thanks

[enochtsang]

Sorry about the lack of detail.

This is the section of code I would run. 10.1.30.134 is the ip of an rsyslog server.

package main

import (
    "github.com/nathanaelle/syslog5424"
    "time"
    "log"
)

type someSD struct {
    Message string
    Errno   int
}

func main() {
    syslog5424.Now = func() time.Time {
        t, _ := time.ParseInLocation("2006-01-02T15:04:00Z", "2014-12-20T14:04:00Z", time.UTC)
        return t
    }

    sl_conn,err := syslog5424.Dial("tcp", "10.1.30.134:514")
    if err != nil {
        log.Fatal(err)
    }

    syslog, err := syslog5424.New(sl_conn, syslog5424.LOG_DAEMON|syslog5424.LOG_WARNING, "test-app")
    if err != nil {
        log.Fatal(err)
    }
    syslog.TestMode()

    conflog := syslog.SubSyslog("configuration")

    // using standard "log" API from golang
    logger_info_conf := conflog.Channel(syslog5424.LOG_INFO).Logger("INFO : ")
    logger_err_conf := conflog.Channel(syslog5424.LOG_ERR).Logger("ERR : ")

    // this is not logged because line 25 tell to syslog to log syslog5424.LOG_WARNING or higher
    logger_info_conf.Print("doing some stuff but not logged")

    logger_err_conf.Print("doing some stuff")

    // using internal API
    conflog.Channel(syslog5424.LOG_ERR).Log("another message with structured data", someSD{"some message", 42})

    // closing the connection and flushing all remaining logs
    time.Sleep(time.Second)
    sl_conn.End()
}

When I use a windows client to run the above code, the server outputs:

Dec 20 14:04:00 localhost test-app/configuration[1234] ERR : doing some stuff
Dec 20 14:04:00 localhost test-app/configuration[1234] another message with structured data
Dec  8 11:51:50 enoch-tsang-vm rsyslogd-2165: netstream session 0x7f2ca0005d10 will be closed due to error
 [try http://www.rsyslog.com/e/2165 ]

When I use a linux machine to run the above code, the server outputs:

Dec 20 14:04:00 localhost test-app/configuration[1234] ERR : doing some stuff
Dec 20 14:04:00 localhost test-app/configuration[1234] another message with structured data

Do you have any idea why that error might be occurring? I've tested this with a couple windows machines and a couple linux machines with the same result.

[nathanaelle]

The code use directly "net" package, so there is no specific reason in my code for this issue.

But, I found a typo, so I patched it. I don't think this typo explain the issue.

Did you try to use TCPDump to see what rsyslog receive ?

I'm reading https://github.com/golang/go/labels/OS-Windows to see if there is something explaining the issue.

the syslog hello world is (not compiled) :

package main
import (
"net"
"io"
)

func main() {
tcp,_ := net.Dial("tcp", "10.1.30.134:514")
defer tcp.Close()

io.WriteString(tcp, "<27>1 2014-12-20T14:04:00Z localhost test-app/configuration 1234 - - ERR : doing some stuff\n")
}

so I hope this snippet will produce the same error. Can you test it ?

thanks

[enochtsang]

That snippet doesn't produce the same error. Just

Dec 20 14:04:00 localhost test-app/configuration[1234] ERR : doing some stuff

BTW, I commend you for your detective skills :)

[nathanaelle]

I need to know more details about this error. So, can you run rsyslog in debug mode ? See http://www.rsyslog.com/doc/v8-stable/troubleshooting/

because the error -2165 must produce an debug message with this template error during recv on NSD %v: %v and I need the two values :)

with my investigation, I found a possible explanation… a race condition at the terminaison of the socket in my code.

If I'm right, I resolved it on other projects with extra parameter : a sync.WaitGroup or a chan struct{}. The adaptation began for syslog5424, but not finished yet. In the meantime, context.Context became stable… so it may provide a more generic solution.

thank for your compliment, and thanks for your patience :)

[nathanaelle]

TLDR : this is an technical explanation of the issue…

golang doesn't wait the end of goroutine if main() ends

For sending messages and handling the the need of redial in case of server side socket terminaison, I need to queue messages and send them and if send is reported ok dequeue them. I use a goroutine for this task.

But if the main() ends before the socket is closed… the system will close on its own way. So, it may produce some OOB message or TCP error that can be detected by the peer, and produce an errno for the recv() syscall in peer.

so I need to know the errno produced to be certain of my explanation :)

[enochtsang]

Hey I pulled your latest code and it didn't resolve the issue.

But here's the other error message I get that follows the template when I run in debug mode.

error during recv on NSD 0x7f8d2c000ed0: Connection reset by peer

[nathanaelle]

thank you :)

[nathanaelle]

Windows seems to send a RST packet in case of unclosed socket at exit. And I found that I forgot a Close() in my memory buffer that implements net.Conn.

[nathanaelle]

I'm sorry, I forgot to tell you to try the last version 2 days ago.

[enochtsang]

I was out for the weekend, no worries. Good news it works! Thanks so much :)