cwtch/testing/cwtch_peer_server_integration_test.go

package testing

import (
	app2 "cwtch.im/cwtch/app"
	"cwtch.im/cwtch/app/utils"
	"cwtch.im/cwtch/event"
	"cwtch.im/cwtch/event/bridge"
	"cwtch.im/cwtch/model"
	"cwtch.im/cwtch/peer"
	"cwtch.im/cwtch/protocol/connections"
	cwtchserver "cwtch.im/cwtch/server"
	"fmt"
	"git.openprivacy.ca/openprivacy/libricochet-go/connectivity"
	"git.openprivacy.ca/openprivacy/libricochet-go/log"
	"golang.org/x/net/proxy"
	"os"
	"os/user"
	"path"
	"runtime"
	"runtime/pprof"
	"testing"
	"time"
)

const (
	serverKeyfile = "./../server/app/private_key"
	localKeyfile  = "./private_key"
)

var (
	aliceLines = []string{"Hello, I'm Alice", "bye"}
	bobLines   = []string{"Hi, my name is Bob.", "toodles", "welcome"}
	carolLines = []string{"Howdy, thanks!"}
)

func printAndCountVerifedTimeline(t *testing.T, timeline []model.Message) int {
	numVerified := 0
	for _, message := range timeline {
		fmt.Printf("%v %v> %s\n", message.Timestamp, message.PeerID, message.Message)
		numVerified++
	}
	return numVerified
}

func serverCheck(t *testing.T, serverAddr string) bool {
	torDialer, err := proxy.SOCKS5("tcp", "127.0.0.1:9050", nil, proxy.Direct)
	if err != nil {
		t.Logf("Could not get SOCKS5 proxy: %v", err)
		return false
	}

	// Doesn't seem to be a way to turn the default timeout of 2 minutes down
	conn, err := torDialer.Dial("tcp", serverAddr+".onion:9878")
	if err != nil {
		t.Logf("Could not dial %v: %v", serverAddr, err)
		return false
	}

	conn.Close()
	return true
}

func waitForPeerGroupConnection(t *testing.T, peer peer.CwtchPeer, groupID string) {
	for {
		fmt.Printf("%v checking group conection...\n", peer.GetName())
		state, ok := peer.GetGroupState(groupID)
		if ok {
			fmt.Printf("Waiting for Peer %v to join group %v - state: %v\n", peer.GetName(), groupID, state)
			if state == connections.FAILED {
				t.Fatalf("%v could not connect to %v", peer.GetOnion(), groupID)
			}
			if state != connections.SYNCED {
				fmt.Printf("peer %v  %v waiting connect to group %v, currently: %v\n", peer.GetName(), peer.GetOnion(), groupID, connections.ConnectionStateName[state])
				time.Sleep(time.Second * 5)
				continue
			} else {
				fmt.Printf("peer %v  %v CONNECTED to group %v\n", peer.GetName(), peer.GetOnion(), groupID)
				break
			}
		}
	}
	return
}

func waitForPeerPeerConnection(t *testing.T, peera peer.CwtchPeer, peerb peer.CwtchPeer) {
	for {
		state, ok := peera.GetPeerState(peerb.GetOnion())
		if ok {
			//log.Infof("Waiting for Peer %v to peer with peer: %v - state: %v\n", peera.GetProfile().Name, peerb.GetProfile().Name, state)
			if state == connections.FAILED {
				t.Fatalf("%v could not connect to %v", peera.GetOnion(), peerb.GetOnion())
			}
			if state != connections.AUTHENTICATED {
				fmt.Printf("peer %v waiting connect to peer %v, currently: %v\n", peera.GetOnion(), peerb.GetOnion(), connections.ConnectionStateName[state])
				time.Sleep(time.Second * 5)
				continue
			} else {
				fmt.Printf("%v CONNECTED and AUTHED to %v\n", peera.GetName(), peerb.GetName())
				break
			}
		}
	}
	return
}

func TestCwtchPeerIntegration(t *testing.T) {
	numGoRoutinesStart := runtime.NumGoroutine()

	log.AddEverythingFromPattern("connectivity")
	log.SetLevel(log.LevelDebug)
	log.ExcludeFromPattern("connection/connection")
	log.ExcludeFromPattern("outbound/3dhauthchannel")
	log.ExcludeFromPattern("event/eventmanager")
	log.ExcludeFromPattern("pipeBridge")
	log.ExcludeFromPattern("tapir")
	os.RemoveAll("tor")
	acn, err := connectivity.StartTor(".", "")
	if err != nil {
		t.Fatalf("Could not start Tor: %v", err)
	}

	// ***** Cwtch Server management *****
	var server *cwtchserver.Server

	serverOnline := false
	var serverAddr string

	if !serverOnline {
		// launch app with new key
		fmt.Println("No server found!")
		server = new(cwtchserver.Server)
		fmt.Println("Starting cwtch server...")
		os.Remove("server-test.json")
		config := cwtchserver.LoadConfig(".", "server-test.json")
		identity := config.Identity()
		serverAddr = identity.Hostname()
		go server.Run(acn, config)

		// let tor get established
		fmt.Printf("Establishing Tor hidden service: %v...\n", serverAddr)
	} else {
		fmt.Printf("Found existing cwtch server %v, using for tests...\n", serverAddr)
	}

	numGoRoutinesPostServer := runtime.NumGoroutine()

	app := app2.NewApp(acn, "./storage")

	usr, _ := user.Current()
	cwtchDir := path.Join(usr.HomeDir, ".cwtch")
	os.Mkdir(cwtchDir, 0700)
	os.RemoveAll(path.Join(cwtchDir, "testing"))
	os.Mkdir(path.Join(cwtchDir, "testing"), 0700)
	bridgeClient := bridge.NewPipeBridgeClient(path.Join(cwtchDir, "testing/clientPipe"), path.Join(cwtchDir, "testing/servicePipe"))
	bridgeService := bridge.NewPipeBridgeService(path.Join(cwtchDir, "testing/servicePipe"), path.Join(cwtchDir, "testing/clientPipe"))
	appClient := app2.NewAppClient("./storage", bridgeClient)
	appService := app2.NewAppService(acn, "./storage", bridgeService)

	numGoRoutinesPostAppStart := runtime.NumGoroutine()

	// ***** cwtchPeer setup *****

	fmt.Println("Creating Alice...")
	app.CreatePeer("alice", "asdfasdf")

	fmt.Println("Creating Bob...")
	app.CreatePeer("bob", "asdfasdf")

	fmt.Println("Creating Carol...")
	appClient.CreatePeer("carol", "asdfasdf")

	alice := utils.WaitGetPeer(app, "alice")
	fmt.Println("Alice created:", alice.GetOnion())
	alice.AutoHandleEvents([]event.Type{event.PeerStateChange, event.ServerStateChange, event.NewGroupInvite})

	bob := utils.WaitGetPeer(app, "bob")
	fmt.Println("Bob created:", bob.GetOnion())
	bob.AutoHandleEvents([]event.Type{event.PeerStateChange, event.ServerStateChange, event.NewGroupInvite})

	carol := utils.WaitGetPeer(appClient, "carol")
	fmt.Println("Carol created:", carol.GetOnion())
	carol.AutoHandleEvents([]event.Type{event.PeerStateChange, event.ServerStateChange, event.NewGroupInvite})

	app.LaunchPeers()
	appClient.LaunchPeers()

	fmt.Println("Waiting for Alice, Bob, and Carol to connect with onion network...")
	time.Sleep(time.Second * 60)
	numGoRoutinesPostPeerStart := runtime.NumGoroutine()

	// ***** Peering, server joining, group creation / invite *****

	fmt.Println("Alice joining server...")
	alice.JoinServer(serverAddr)

	fmt.Println("Alice peering with Bob...")
	alice.AddContact("Bob", bob.GetOnion(), false) // Add contact so we can track connection state
	alice.PeerWithOnion(bob.GetOnion())

	fmt.Println("Alice peering with Carol...")
	alice.AddContact("Carol", carol.GetOnion(), false)
	alice.PeerWithOnion(carol.GetOnion())

	fmt.Println("Creating group on ", serverAddr, "...")
	groupID, _, err := alice.StartGroup(serverAddr)
	fmt.Printf("Created group: %v!\n", groupID)
	if err != nil {
		t.Errorf("Failed to init group: %v", err)
		return
	}

	fmt.Println("Waiting for alice to join server...")
	waitForPeerGroupConnection(t, alice, groupID)

	fmt.Println("Waiting for alice and Bob to peer...")
	waitForPeerPeerConnection(t, alice, bob)

	fmt.Println("Alice inviting Bob to group...")
	err = alice.InviteOnionToGroup(bob.GetOnion(), groupID)
	if err != nil {
		t.Fatalf("Error for Alice inviting Bob to group: %v", err)
	}

	time.Sleep(time.Second * 5)

	fmt.Println("Bob examining groups and accepting invites...")
	for _, groupID := range bob.GetGroups() {
		group := bob.GetGroup(groupID)
		fmt.Printf("Bob group: %v (Accepted: %v)\n", group.GroupID, group.Accepted)
		if group.Accepted == false {
			fmt.Printf("Bob received and accepting group invite: %v\n", group.GroupID)
			bob.AcceptInvite(group.GroupID)
		}
	}

	numGoRoutinesPostServerConnect := runtime.NumGoroutine()

	// ***** Conversation *****

	fmt.Println("Starting conversation in group...")
	// Conversation
	fmt.Println("Alice> ", aliceLines[0])
	err = alice.SendMessageToGroup(groupID, aliceLines[0])
	if err != nil {
		t.Fatalf("Alice failed to send a message to the group: %v", err)
	}
	time.Sleep(time.Second * 10)

	fmt.Println("Bob> ", bobLines[0])
	err = bob.SendMessageToGroup(groupID, bobLines[0])
	if err != nil {
		t.Fatalf("Bob failed to send a message to the group: %v", err)
	}
	time.Sleep(time.Second * 10)

	fmt.Println("Alice> ", aliceLines[1])
	alice.SendMessageToGroup(groupID, aliceLines[1])
	time.Sleep(time.Second * 10)

	fmt.Println("Bob> ", bobLines[1])
	bob.SendMessageToGroup(groupID, bobLines[1])
	time.Sleep(time.Second * 10)

	fmt.Println("Alice inviting Carol to group...")
	err = alice.InviteOnionToGroup(carol.GetOnion(), groupID)
	if err != nil {
		t.Fatalf("Error for Alice inviting Carol to group: %v", err)
	}
	time.Sleep(time.Second * 10)
	fmt.Println("Carol examining groups and accepting invites...")
	for _, groupID := range carol.GetGroups() {
		group := carol.GetGroup(groupID)
		fmt.Printf("Carol group: %v (Accepted: %v)\n", group.GroupID, group.Accepted)
		if group.Accepted == false {
			fmt.Printf("Carol received and accepting group invite: %v\n", group.GroupID)
			carol.AcceptInvite(group.GroupID)
		}
	}

	fmt.Println("Shutting down Alice...")
	app.ShutdownPeer(alice.GetOnion())
	time.Sleep(time.Second * 5)
	numGoRoutinesPostAlice := runtime.NumGoroutine()

	fmt.Println("Carol joining server...")
	carol.JoinServer(serverAddr)
	waitForPeerGroupConnection(t, carol, groupID)
	numGoRotinesPostCarolConnect := runtime.NumGoroutine()

	fmt.Println("Bob> ", bobLines[2])
	bob.SendMessageToGroup(groupID, bobLines[2])
	time.Sleep(time.Second * 10)

	fmt.Println("Carol> ", carolLines[0])
	carol.SendMessageToGroup(groupID, carolLines[0])
	time.Sleep(time.Second * 10)

	// ***** Verify Test *****

	fmt.Println("Final syncing time...")
	time.Sleep(time.Second * 30)

	alicesGroup := alice.GetGroup(groupID)
	if alicesGroup == nil {
		t.Error("aliceGroup == nil")
		return
	}

	fmt.Printf("Alice's TimeLine:\n")
	aliceVerified := printAndCountVerifedTimeline(t, alicesGroup.GetTimeline())
	if aliceVerified != 4 {
		t.Errorf("Alice did not have 4 verified messages")
	}

	bobsGroup := bob.GetGroup(groupID)
	if bobsGroup == nil {
		t.Error("bobGroup == nil")
		return
	}
	fmt.Printf("Bob's TimeLine:\n")
	bobVerified := printAndCountVerifedTimeline(t, bobsGroup.GetTimeline())
	if bobVerified != 6 {
		t.Errorf("Bob did not have 5 verified messages")
	}

	carolsGroup := carol.GetGroup(groupID)
	fmt.Printf("Carol's TimeLine:\n")
	carolVerified := printAndCountVerifedTimeline(t, carolsGroup.GetTimeline())
	if carolVerified != 6 {
		t.Errorf("Carol did not have 3 verified messages")
	}

	if len(alicesGroup.GetTimeline()) != 4 {
		t.Errorf("Alice's timeline does not have all messages")
	} else {
		// check message 0,1,2,3
		aliceGroupTimeline := alicesGroup.GetTimeline()
		if aliceGroupTimeline[0].Message != aliceLines[0] || aliceGroupTimeline[1].Message != bobLines[0] ||
			aliceGroupTimeline[2].Message != aliceLines[1] || aliceGroupTimeline[3].Message != bobLines[1] {
			t.Errorf("Some of Alice's timeline messages did not have the expected content!")
		}
	}

	if len(bobsGroup.GetTimeline()) != 6 {
		t.Errorf("Bob's timeline does not have all messages")
	} else {
		// check message 0,1,2,3,4,5
		bobGroupTimeline := bobsGroup.GetTimeline()
		if bobGroupTimeline[0].Message != aliceLines[0] || bobGroupTimeline[1].Message != bobLines[0] ||
			bobGroupTimeline[2].Message != aliceLines[1] || bobGroupTimeline[3].Message != bobLines[1] ||
			bobGroupTimeline[4].Message != bobLines[2] || bobGroupTimeline[5].Message != carolLines[0] {
			t.Errorf("Some of Bob's timeline messages did not have the expected content!")
		}
	}

	if len(carolsGroup.GetTimeline()) != 6 {
		t.Errorf("Carol's timeline does not have all messages")
	} else {
		// check message 0,1,2,3,4,5
		carolGroupTimeline := carolsGroup.GetTimeline()
		if carolGroupTimeline[0].Message != aliceLines[0] || carolGroupTimeline[1].Message != bobLines[0] ||
			carolGroupTimeline[2].Message != aliceLines[1] || carolGroupTimeline[3].Message != bobLines[1] ||
			carolGroupTimeline[4].Message != bobLines[2] || carolGroupTimeline[5].Message != carolLines[0] {
			t.Errorf("Some of Carol's timeline messages did not have the expected content!")
		}
	}

	fmt.Println("Shutting down Bob...")
	app.ShutdownPeer(bob.GetOnion())
	time.Sleep(time.Second * 3)
	numGoRoutinesPostBob := runtime.NumGoroutine()
	if server != nil {
		fmt.Println("Shutting down server...")
		server.Shutdown()
		time.Sleep(time.Second * 3)
	}
	numGoRoutinesPostServerShutdown := runtime.NumGoroutine()

	fmt.Println("Shutting down Carol...")
	appClient.ShutdownPeer(carol.GetOnion())
	time.Sleep(time.Second * 3)
	numGoRoutinesPostCarol := runtime.NumGoroutine()

	fmt.Println("Shutting down apps...")
	fmt.Printf("app Shutdown: %v\n", runtime.NumGoroutine())
	app.Shutdown()
	fmt.Printf("appClientShutdown: %v\n", runtime.NumGoroutine())
	appClient.Shutdown()
	fmt.Printf("appServiceShutdown: %v\n", runtime.NumGoroutine())
	appService.Shutdown()

	fmt.Printf("bridgeClientShutdown: %v\n", runtime.NumGoroutine())
	bridgeClient.Shutdown()
	time.Sleep(2 * time.Second)

	fmt.Printf("brideServiceShutdown: %v\n", runtime.NumGoroutine())
	bridgeService.Shutdown()
	time.Sleep(2 * time.Second)

	fmt.Printf("Done shutdown: %v\n", runtime.NumGoroutine())
	numGoRoutinesPostAppShutdown := runtime.NumGoroutine()

	fmt.Println("Shutting down ACN...")
	acn.Close()
	time.Sleep(time.Second * 2)  // Server ^^ has a 5 second loop attempting reconnect before exiting
	time.Sleep(time.Second * 30) // the network status plugin might keep goroutines alive for a minute before killing them
	numGoRoutinesPostACN := runtime.NumGoroutine()

	// Printing out the current goroutines
	// Very useful if we are leaking any.
	pprof.Lookup("goroutine").WriteTo(os.Stdout, 1)

	fmt.Printf("numGoRoutinesStart: %v\nnumGoRoutinesPostServer: %v\nnumGoRoutinesPostAppStart: %v\nnumGoRoutinesPostPeerStart: %v\nnumGoRoutinesPostPeerAndServerConnect: %v\n"+
		"numGoRoutinesPostAlice: %v\nnumGoRotinesPostCarolConnect: %v\nnumGoRoutinesPostBob: %v\nnumGoRoutinesPostServerShutdown: %v\nnumGoRoutinesPostCarol: %v\nnumGoRoutinesPostAppShutdown: %v\nnumGoRoutinesPostACN: %v\n",
		numGoRoutinesStart, numGoRoutinesPostServer, numGoRoutinesPostAppStart, numGoRoutinesPostPeerStart, numGoRoutinesPostServerConnect,
		numGoRoutinesPostAlice, numGoRotinesPostCarolConnect, numGoRoutinesPostBob, numGoRoutinesPostServerShutdown, numGoRoutinesPostCarol, numGoRoutinesPostAppShutdown, numGoRoutinesPostACN)

	if numGoRoutinesStart != numGoRoutinesPostACN {
		t.Errorf("Number of GoRoutines at start (%v) does not match number of goRoutines after cleanup of peers and servers (%v), clean up failed, leak detected!", numGoRoutinesStart, numGoRoutinesPostACN)
	}

}