func testLogging() {
// Check that os.Stderr is the (only) default logger
check(util.LoggersCount(), 1)
util.LoggerRemove(os.Stderr)
check(util.LoggersCount(), 0)
// Check that default loglevel is 0
check(util.LogLevel, 0)
flushy := new(FlushableBuffer)
synchy := new(SyncableBuffer)
util.LoggerAdd(flushy)
check(util.LoggersCount(), 1)
util.LoggerAdd(synchy)
check(util.LoggersCount(), 2)
util.LogLevel = 4
defer func() { util.LogLevel = 0 }()
oldfac := util.BacklogFactor
defer func() { util.BacklogFactor = oldfac }()
util.BacklogFactor = 4
util.Log(0, "a0") // 0
time.Sleep(200 * time.Millisecond)
for i := 1; i <= 4; i++ {
util.Log(i, "a%d", i)
} // 1,2,3,4
for i := 0; i <= 4; i++ {
util.Log(i, "b%d", i)
} // 0,1,2,3
for i := 0; i <= 4; i++ {
util.Log(i, "c%d", i)
} // 0,1,2
for i := 0; i <= 4; i++ {
util.Log(i, "d%d", i)
} // 0,1
for i := 0; i <= 4; i++ {
util.Log(i, "e%d", i)
} // 0,1
util.Log(1, "x") // should be logged because when this Log() is executed, the backlog is only 15 long
util.Log(1, "y") // should NOT be logged after the previous "x" the backlog is 16=4*BacklogFactor long
check(flushy.Flushes, 0)
check(synchy.Flushes, 0)
time.Sleep(2 * time.Second)
check(flushy.Flushes, 1)
check(synchy.Flushes, 1)
util.Log(5, "Shouldnotbelogged!")
util.Log(4, "Shouldbelogged!")
time.Sleep(200 * time.Millisecond)
check(flushy.Flushes, 2)
check(synchy.Flushes, 2)
util.LoggersSuspend()
check(util.LoggersCount(), 0)
util.LoggerAdd(os.Stderr)
check(util.LoggersCount(), 1)
util.LoggersSuspend()
check(util.LoggersCount(), 0)
util.Log(0, "This should disappear in the void")
buffy := new(bytes.Buffer)
util.LoggerAdd(buffy)
joke := "Sagt die Katze zum Verkäufer: Ich hab nicht genug Mäuse. Kann ich auch in Ratten zahlen?"
util.Log(0, joke)
time.Sleep(200 * time.Millisecond)
check(strings.Index(buffy.String(), joke) >= 0, true)
check(util.LoggersCount(), 1)
util.LoggersRestore()
check(util.LoggersCount(), 1)
util.LoggersRestore()
check(util.LoggersCount(), 2)
util.Log(0, "foo")
time.Sleep(200 * time.Millisecond)
lines := flushy.Buf.Split("\n")
for i := range lines {
if strings.Index(lines[i], "missing") < 0 {
idx := strings.LastIndex(lines[i], " ")
lines[i] = lines[i][idx+1:]
} else {
idx := strings.Index(lines[i], " missing")
lines[i] = lines[i][idx-2 : idx]
}
}
check(lines, []string{"a0", "a1", "a2", "a3", "a4", "b0", "b1", "b2", "b3", "c0", "c1", "c2", "d0", "d1", "e0", "e1", "x", "10", "Shouldbelogged!", "foo", ""})
check(flushy.Buf.String(), synchy.Buf.String())
// Reset loggers so that only os.Stderr is a logger
for util.LoggersCount() > 0 {
util.LoggersRestore()
}
util.LoggerAdd(os.Stderr)
}
// Unit tests for the package go-susi/message.
func Message_test() {
fmt.Printf("\n==== message ===\n\n")
getFJU() // clean up remnants from DB_test()
go func() {
defer func() { recover() }()
message.DistributeForeignJobUpdates()
}()
// This is a nasty trick. Send nil over the channel to cause a
// a panic in the message.DistributeForeignJobUpdates()
// goroutine so that it will terminate.
// ATM it's not actually necessary to make it terminate but it's
// a precaution against future test code that may not expect someone
// to be reading from this channel.
defer func() { db.ForeignJobUpdates <- nil }()
nohost := error_string(<-message.Peer("Broken").Ask("foo", ""))
if nohost == "lookup Broken: No address associated with hostname" {
nohost = "lookup Broken: no such host"
}
check(hasWords(nohost, "lookup", "no such host"), "")
check(error_string(<-message.Peer("192.168.250.128:55").Ask("foo", "")), "PeerConnection.Ask: No key known for peer 192.168.250.128:55")
check(hasWords(error_string(<-message.Peer("127.0.0.1:55551").Ask("foo", "bar")), "connection refused"), "")
listen()
defer func() { listen_stop() }()
listen_address = config.IP + ":" + listen_port
init_keys()
keys[0] = "MessageTestKey"
db.ServerUpdate(hash("xml(key(%v)source(%v))", keys[0], listen_address))
message.Peer(listen_address).SetGoSusi(true)
check(message.Peer(listen_address).IsGoSusi(), true)
message.Peer(listen_address).SetGoSusi(false)
check(message.Peer(listen_address).IsGoSusi(), false)
message.Peer(listen_address).SetGoSusi(true)
check(message.Peer(listen_address).IsGoSusi(), true)
check(message.Peer(listen_address).Downtime(), 0)
t0 := time.Now()
message.Peer(listen_address).Tell("<xml><header>Hallo</header></xml>", keys[0])
check(wait(t0, "Hallo").XML.Text("header"), "Hallo")
t0 = time.Now()
message.Peer(listen_address).Tell("<xml><header>Aloha</header></xml>", "")
check(wait(t0, "Aloha").XML.Text("header"), "Aloha")
// suppress error logs
oldlevel := util.LogLevel
util.LogLevel = -1
check(error_string(<-message.Peer(listen_address).Ask("<xml><header>gosa_query_jobdb</header></xml>", config.ModuleKey["[GOsaPackages]"])), "")
check(error_string(<-message.Peer(listen_address).Ask("<xml><header>whatever</header></xml>", config.ModuleKey["[GOsaPackages]"])), "Communication error in Ask()")
for repcount := 0; repcount < 2; repcount++ {
// shut down listener
listen_stop()
// wait 3 seconds and check downtime
time.Sleep(time.Duration(3+repcount) * time.Second)
downtime := int64((message.Peer(listen_address).Downtime() + 500*time.Millisecond) / time.Second)
check(downtime, 3+repcount)
// verify that connection is really down
t0 = time.Now()
message.Peer(listen_address).Tell("<xml><header>down</header></xml>", keys[0])
check(wait(t0, "down").XML.Text("header"), "")
// restart listener
listen()
// send message and check if the listener receives it
t0 = time.Now()
message.Peer(listen_address).Tell("<xml><header>Wuseldusel</header></xml>", keys[0])
check(wait(t0, "Wuseldusel").XML.Text("header"), "Wuseldusel")
// check that downtime has stopped
check(message.Peer(listen_address).Downtime(), 0)
}
// set maximum downtime before removal
defer func(mpd time.Duration) { config.MaxPeerDowntime = mpd }(config.MaxPeerDowntime)
config.MaxPeerDowntime = 4 * time.Second
time.Sleep(6 * time.Second) // we need to wait for the old 10s pinger to expire
// stop listener
listen_stop()
// ping to make handleConnection() aware that we're down
message.Peer(listen_address).Tell("<xml><header>Ping</header></xml>", keys[0])
time.Sleep(1 * time.Second)
message.Peer(listen_address).Tell("<xml><header>Ping</header></xml>", keys[0])
time.Sleep(1 * time.Second)
// check we haven't been removed from serverdb, yet
check(db.ServerKeys(listen_address), []string{keys[0]})
time.Sleep(3 * time.Second)
// ping again. This time handleConnection() should notice we're down to long
message.Peer(listen_address).Tell("<xml><header>Ping</header></xml>", keys[0])
time.Sleep(1 * time.Second)
// check that we've been removed from serverdb
check(db.ServerKeys(listen_address), []string{})
// restore old log level
time.Sleep(1 * time.Second)
util.LogLevel = oldlevel
nohost = error_string(<-message.Peer("broken").Ask("", ""))
if nohost == "lookup broken: No address associated with hostname" {
nohost = "lookup broken: no such host"
}
check(hasWords(nohost, "lookup", "no such host"), "")
check(error_string(<-message.Peer("doesnotexist.domain:10").Ask("", "")), "lookup doesnotexist.domain: no such host")
util.LoggersSuspend()
oldloglevel := util.LogLevel
defer func() { util.LoggersRestore(); util.LogLevel = oldloglevel }()
var buffy bytes.Buffer
util.LoggerAdd(&buffy)
util.LogLevel = 2 // we want all messages, including INFO! and DEBUG!
client := xml.NewHash("xml", "header", "new_foreign_client")
client.Add("source", config.ServerSourceAddress)
client.Add("target", "127.0.0.1:12345")
client.Add("client", listen_address)
client.Add("macaddress", "11:22:33:44:55:66")
keys[len(keys)-1] = "weissnich"
client.Add("key", keys[len(keys)-1])
db.ClientUpdate(client)
t0 = time.Now()
message.Client(listen_address).Tell("<xml><header>Alle meine Entchen</header></xml>", 0)
time.Sleep(reply_timeout)
check(get(t0), []*queueElement{})
check(hasWords(buffy.String(), "ERROR", "Cannot send message"), "")
buffy.Reset()
t0 = time.Now()
message.Client(listen_address).Tell("<xml><header>Alle meine Hündchen</header></xml>", -1200*time.Millisecond)
time.Sleep(reply_timeout)
check(get(t0), []*queueElement{})
check(hasWords(buffy.String(), "ERROR", "Cannot send message"), "")
buffy.Reset()
t0 = time.Now()
message.Client(listen_address).Tell("<xml><header>Alle meine Kätzchen</header></xml>", 2*time.Second)
time.Sleep(3 * time.Second)
check(get(t0), []*queueElement{})
check(hasWords(buffy.String(), "ERROR", "Cannot send message", "Attempt #1", "Attempt #2"), "")
buffy.Reset()
t0 = time.Now()
message.Client(listen_address).Tell("<xml><header>Alle meine Häschen</header></xml>", 3*time.Second)
time.Sleep(1500 * time.Millisecond)
listen()
time.Sleep(1 * time.Second)
x := get(t0)
if check(len(x), 1) {
check(x[0].XML.Text("header"), "Alle meine Häschen")
check(x[0].Key, keys[len(keys)-1])
}
check(hasWords(buffy.String(), "Attempt #1", "Attempt #2", "Successfully sent message"), "")
buffy.Reset()
t0 = time.Now()
message.Client(listen_address).Tell("<xml><header>Alle meine Vöglein</header></xml>", -1200*time.Millisecond)
time.Sleep(reply_timeout)
x = get(t0)
if check(len(x), 1) {
check(x[0].XML.Text("header"), "Alle meine Vöglein")
check(x[0].Key, keys[len(keys)-1])
}
check(hasWords(buffy.String(), "Successfully sent message"), "")
listen_stop()
}
// Unit tests for the package github.com/mbenkmann/golib/util.
func Util_test() {
fmt.Printf("\n==== util ===\n\n")
addr, err := util.Resolve("1.2.3.4", "")
check(err, nil)
check(addr, "1.2.3.4")
addr, err = util.Resolve("1.2.3.4:5", "")
check(err, nil)
check(addr, "1.2.3.4:5")
addr, err = util.Resolve("::1:5", "")
check(err, nil)
check(addr, "[::1:5]")
addr, err = util.Resolve("localhost:65535", "")
check(err, nil)
check(addr, "127.0.0.1:65535")
addr, err = util.Resolve("localhost", "")
check(err, nil)
check(addr, "127.0.0.1")
addr, err = util.Resolve("::1", "")
check(err, nil)
check(addr, "127.0.0.1")
addr, err = util.Resolve("[::1]", "")
check(err, nil)
check(addr, "127.0.0.1")
addr, err = util.Resolve("[::1]:12345", "")
check(err, nil)
check(addr, "127.0.0.1:12345")
addr, err = util.Resolve("localhost:65535", "foo")
check(err, nil)
check(addr, "foo:65535")
addr, err = util.Resolve("localhost", "foo")
check(err, nil)
check(addr, "foo")
addr, err = util.Resolve("::1", "foo")
check(err, nil)
check(addr, "foo")
addr, err = util.Resolve("[::1]", "foo")
check(err, nil)
check(addr, "foo")
addr, err = util.Resolve("[::1]:12345", "foo")
check(err, nil)
check(addr, "foo:12345")
addr, err = util.Resolve("", "")
check(hasWords(err, "no", "such", "host"), "")
check(addr, "")
addr, err = util.Resolve(":10", "")
check(hasWords(err, "no", "such", "host"), "")
check(addr, ":10")
check(util.WaitForDNS(3*time.Second), true)
h, _ := exec.Command("hostname").CombinedOutput()
hostname := strings.TrimSpace(string(h))
ipp, _ := exec.Command("hostname", "-I").CombinedOutput()
ips := strings.Fields(strings.TrimSpace(string(ipp)))
addr, err = util.Resolve(hostname+":234", config.IP)
check(err, nil)
ip := ""
for _, ip2 := range ips {
if addr == ip2+":234" {
ip = ip2
}
}
check(addr, ip+":234")
testLogging()
buf := make([]byte, 80)
for i := range buf {
buf[i] = byte(util_test_rng.Intn(26) + 'a')
}
crap1 := &crappyConnection1{}
n, err := util.WriteAll(crap1, buf)
check(string(*crap1), string(buf))
check(n, len(buf))
check(err, nil)
crap2 := &crappyConnection2{}
n, err = util.WriteAll(crap2, buf)
check(string(*crap2), string(buf))
check(n, len(buf))
check(err, nil)
stalled1 := &stalledConnection1{}
n, err = util.WriteAll(stalled1, buf)
check(string(*stalled1), string(buf[0:16]))
check(n, 16)
check(err, io.ErrShortWrite)
stalled2 := &stalledConnection2{}
n, err = util.WriteAll(stalled2, buf)
check(string(*stalled2), string(buf[0:16]))
check(n, 16)
check(err, io.ErrShortWrite)
broken := &brokenConnection{}
n, err = util.WriteAll(broken, buf)
check(string(*broken), string(buf[0:16]))
check(n, 16)
check(err, io.ErrClosedPipe)
panicker := func() {
foobar = "bar"
panic("foo")
}
var buffy bytes.Buffer
util.LoggersSuspend()
util.LoggerAdd(&buffy)
defer util.LoggersRestore()
util.WithPanicHandler(panicker)
time.Sleep(200 * time.Millisecond) // make sure log message is written out
check(foobar, "bar")
check(len(buffy.String()) > 10, true)
listener, err := net.Listen("tcp", "127.0.0.1:39390")
if err != nil {
panic(err)
}
go func() {
r, err := listener.Accept()
if err != nil {
panic(err)
}
buf := make([]byte, 1)
r.Read(buf)
time.Sleep(10 * time.Second)
r.Read(buf)
}()
long := make([]byte, 10000000)
longstr := string(long)
buffy.Reset()
t0 := time.Now()
util.SendLnTo("127.0.0.1:39390", longstr, 5*time.Second)
duration := time.Since(t0)
check(duration > 4*time.Second && duration < 6*time.Second, true)
time.Sleep(200 * time.Millisecond) // make sure log message is written out
check(strings.Contains(buffy.String(), "ERROR"), true)
go func() {
conn, err := listener.Accept()
if err != nil {
panic(err)
}
ioutil.ReadAll(conn)
}()
long = make([]byte, 10000000)
longstr = string(long)
buffy.Reset()
t0 = time.Now()
util.SendLnTo("127.0.0.1:39390", longstr, 5*time.Second)
duration = time.Since(t0)
check(duration < 2*time.Second, true)
time.Sleep(200 * time.Millisecond) // make sure log message is written out
check(buffy.String(), "")
// Test that ReadLn() times out properly
go func() {
_, err := net.Dial("tcp", "127.0.0.1:39390")
if err != nil {
panic(err)
}
}()
conn, err := listener.Accept()
if err != nil {
panic(err)
}
t0 = time.Now()
st, err := util.ReadLn(conn, 5*time.Second)
duration = time.Since(t0)
check(duration > 4*time.Second && duration < 6*time.Second, true)
check(st, "")
check(hasWords(err, "timeout"), "")
// Test that ReadLn() returns io.EOF if last line not terminated by \n
go func() {
conn, err := net.Dial("tcp", "127.0.0.1:39390")
if err != nil {
panic(err)
}
conn.Write([]byte("foo\r"))
conn.Close()
}()
conn, err = listener.Accept()
if err != nil {
panic(err)
}
st, err = util.ReadLn(conn, 5*time.Second)
check(err, io.EOF)
check(st, "foo")
go func() {
conn, err := net.Dial("tcp", "127.0.0.1:39390")
if err != nil {
panic(err)
}
conn.Write([]byte("\r\r\n\rfo\ro\nbar\r\nfoxtrott"))
conn.Close()
}()
conn, err = listener.Accept()
if err != nil {
panic(err)
}
// Test proper trimming of multiple \r
st, err = util.ReadLn(conn, 0)
check(err, nil)
check(st, "")
// Test that the empty first line has actually been read
// and that the next ReadLn() reads the 2nd line
// Also test that negative timeouts work the same as timeout==0
// Also test that \r is not trimmed at start and within line.
st, err = util.ReadLn(conn, -1*time.Second)
check(err, nil)
check(st, "\rfo\ro")
// Check 3rd line
st, err = util.ReadLn(conn, 0)
check(err, nil)
check(st, "bar")
// Check 4th line and io.EOF error
st, err = util.ReadLn(conn, 0)
check(err, io.EOF)
check(st, "foxtrott")
// Test that delayed reads work with timeout==0
go func() {
conn, err := net.Dial("tcp", "127.0.0.1:39390")
if err != nil {
panic(err)
}
time.Sleep(1 * time.Second)
_, err = conn.Write([]byte("foo\r\n"))
if err != nil {
panic(err)
}
time.Sleep(2 * time.Second)
}()
conn, err = listener.Accept()
if err != nil {
panic(err)
}
t0 = time.Now()
st, err = util.ReadLn(conn, time.Duration(0))
duration = time.Since(t0)
check(duration < 2*time.Second, true)
check(duration > 800*time.Millisecond, true)
check(err, nil)
check(st, "foo")
counter := util.Counter(13)
var b1 UintArray = make([]uint64, 100)
var b2 UintArray = make([]uint64, 100)
done := make(chan bool)
fill := func(b UintArray) {
for i := 0; i < 100; i++ {
b[i] = <-counter
time.Sleep(1 * time.Millisecond)
}
done <- true
}
go fill(b1)
go fill(b2)
<-done
<-done
check(sort.IsSorted(&b1), true)
check(sort.IsSorted(&b2), true)
var b3 UintArray = make([]uint64, 200)
i := 0
j := 0
k := 0
for i < 100 || j < 100 {
if i == 100 {
b3[k] = b2[j]
j++
k++
continue
}
if j == 100 {
b3[k] = b1[i]
i++
k++
continue
}
if b1[i] == b2[j] {
check(b1[i] != b2[j], true)
break
}
if b1[i] < b2[j] {
b3[k] = b1[i]
i++
} else {
b3[k] = b2[j]
j++
}
k++
}
one_streak := true
b5 := make([]uint64, 200)
for i := 0; i < 200; i++ {
if i < 100 && b1[i] != uint64(13+i) && b2[i] != uint64(13+i) {
one_streak = false
}
b5[i] = uint64(13 + i)
}
check(b3, b5)
check(one_streak, false) // Check whether goroutines were actually executed concurrently rather than in sequence
tempdir, err := ioutil.TempDir("", "util-test-")
if err != nil {
panic(err)
}
defer os.RemoveAll(tempdir)
fpath := tempdir + "/foo.log"
logfile := util.LogFile(fpath)
check(logfile.Close(), nil)
n, err = util.WriteAll(logfile, []byte("Test"))
check(err, nil)
check(n, 4)
check(logfile.Close(), nil)
n, err = util.WriteAll(logfile, []byte("12"))
check(err, nil)
check(n, 2)
n, err = util.WriteAll(logfile, []byte("3"))
check(err, nil)
check(n, 1)
check(os.Rename(fpath, fpath+".old"), nil)
n, err = util.WriteAll(logfile, []byte("Fo"))
check(err, nil)
check(n, 2)
f2, _ := os.OpenFile(fpath, os.O_WRONLY|os.O_APPEND|os.O_CREATE, 0644)
f2.Write([]byte("o"))
f2.Close()
n, err = util.WriteAll(logfile, []byte("bar"))
check(err, nil)
check(n, 3)
check(logfile.Close(), nil)
data, err := ioutil.ReadFile(fpath)
check(err, nil)
if err == nil {
check(string(data), "Foobar")
}
data, err = ioutil.ReadFile(fpath + ".old")
check(err, nil)
if err == nil {
check(string(data), "Test123")
}
test_time := time.Date(2013, time.January, 20, 14, 7, 21, 0, time.Local)
check(util.MakeTimestamp(test_time), "20130120140721")
test_time = time.Date(2013, time.January, 20, 14, 7, 21, 0, time.UTC)
check(util.MakeTimestamp(test_time), "20130120140721")
test_time = time.Date(2013, time.January, 20, 14, 7, 21, 0, time.FixedZone("Fooistan", 45678))
check(util.MakeTimestamp(test_time), "20130120140721")
illegal := time.Unix(0, 0)
buffy.Reset()
check(util.ParseTimestamp(""), illegal)
time.Sleep(200 * time.Millisecond) // make sure log message is written out
check(strings.Contains(buffy.String(), "ERROR"), true)
buffy.Reset()
check(util.ParseTimestamp("20139910101010"), illegal)
time.Sleep(200 * time.Millisecond) // make sure log message is written out
check(strings.Contains(buffy.String(), "ERROR"), true)
check(util.ParseTimestamp("20131110121314"), time.Date(2013, time.November, 10, 12, 13, 14, 0, time.Local))
check(util.MakeTimestamp(util.ParseTimestamp(util.MakeTimestamp(test_time))), util.MakeTimestamp(test_time))
test_time = test_time.Add(2400 * time.Hour)
check(util.MakeTimestamp(util.ParseTimestamp(util.MakeTimestamp(test_time))), util.MakeTimestamp(test_time))
test_time = test_time.Add(2400 * time.Hour)
check(util.MakeTimestamp(util.ParseTimestamp(util.MakeTimestamp(test_time))), util.MakeTimestamp(test_time))
test_time = test_time.Add(2400 * time.Hour)
check(util.MakeTimestamp(util.ParseTimestamp(util.MakeTimestamp(test_time))), util.MakeTimestamp(test_time))
test_time = test_time.Add(2400 * time.Hour)
check(util.MakeTimestamp(util.ParseTimestamp(util.MakeTimestamp(test_time))), util.MakeTimestamp(test_time))
diff := time.Since(util.ParseTimestamp(util.MakeTimestamp(time.Now())))
if diff < time.Second {
diff = 0
}
check(diff, time.Duration(0))
t0 = time.Now()
util.WaitUntil(t0.Add(-10 * time.Second))
util.WaitUntil(t0.Add(-100 * time.Minute))
dur := time.Now().Sub(t0)
if dur < 1*time.Second {
dur = 0
}
check(dur, 0)
t0 = time.Now()
util.WaitUntil(t0.Add(1200 * time.Millisecond))
dur = time.Now().Sub(t0)
if dur >= 1200*time.Millisecond && dur <= 1300*time.Millisecond {
dur = 1200 * time.Millisecond
}
check(dur, 1200*time.Millisecond)
mess := "WaitUntil(Jesus first birthday) takes forever"
go func() {
util.WaitUntil(time.Date(1, time.December, 25, 0, 0, 0, 0, time.UTC))
mess = ""
}()
time.Sleep(100 * time.Millisecond)
check(mess, "")
mess = "WaitUntil(1000-11-10 00:00:00) takes forever"
go func() {
util.WaitUntil(time.Date(1000, time.October, 11, 0, 0, 0, 0, time.UTC))
mess = ""
}()
time.Sleep(100 * time.Millisecond)
check(mess, "")
testBase64()
}