Added new SGFW DBus method RunDebugCmd() for retrieving firewall state debugging information.

Eliminated heavy SGFW CPU usage due to long loop condition.
Implemented much more helpful print() method for pendingSocksConnection interface.
testfw program updated to show use of new debugging interface.
Removed lots of noisy debug print statements (and moved many to new debugging facility).

sgfw/dbus.go

@@ -6,6 +6,7 @@ import (
 	"net"
 	"path"
 	"strconv"
+	"strings"
 	"time"
 
 	"github.com/godbus/dbus"
@@ -289,6 +290,19 @@ func (ds *dbusServer) AddRuleAsync(scope uint32, rule, policy, guid string) (boo
 	return true, nil
 }
 
+func (ds *dbusServer) RunDebugCmd(cmd string, params string) (string, *dbus.Error) {
+	cmd = strings.ToLower(cmd)
+	result := "Unrecognized debug command: " + cmd
+
+	if cmd == "monitorfds" {
+		result = dumpMonitoredFDs()
+	} else if cmd == "listpending" {
+		result = dumpPendingQueues()
+	}
+
+	return result, nil
+}
+
 func (ds *dbusServer) AddTestVPC(proto string, srcip string, sport uint16, dstip string, dport uint16, hostname string) (bool, *dbus.Error) {
 	log.Warningf("AddTestVPC(proto=%s, srcip=%s, sport=%v, dstip=%s, dport=%v, hostname=%s)\n",
 		proto, srcip, sport, dstip, dport, hostname)

sgfw/policy.go

@@ -279,7 +279,7 @@ func (fw *Firewall) policyForPath(path string) *Policy {
 }
 
 func (p *Policy) processPacket(pkt *nfqueue.NFQPacket, timestamp time.Time, pinfo *procsnitch.Info, optstr string) {
-	fmt.Println("policy processPacket()")
+	fmt.Println("policy processPacket() running against packet...")
 
 	p.lock.Lock()
 	defer p.lock.Unlock()
@@ -554,7 +554,7 @@ func printPacket(pkt *nfqueue.NFQPacket, hostname string, pinfo *procsnitch.Info
 }
 
 func (fw *Firewall) filterPacket(pkt *nfqueue.NFQPacket, timestamp time.Time) {
-	fmt.Println("firewall: filterPacket()")
+	// fmt.Println("firewall: filterPacket()")
 	isudp := pkt.Packet.Layer(layers.LayerTypeUDP) != nil
 
 	if basicAllowPacket(pkt) {

sgfw/prompt.go

@@ -14,11 +14,19 @@ import (
 	"github.com/subgraph/fw-daemon/proc-coroner"
 )
 
+var gPrompter *prompter = nil
+
 func newPrompter(conn *dbus.Conn) *prompter {
 	p := new(prompter)
 	p.cond = sync.NewCond(&p.lock)
 	p.dbusObj = conn.Object("com.subgraph.FirewallPrompt", "/com/subgraph/FirewallPrompt")
 	p.policyMap = make(map[string]*Policy)
+
+	if gPrompter != nil {
+		fmt.Println("Unexpected: global prompter variable was already set!")
+	}
+
+	gPrompter = p
 	go p.promptLoop()
 	return p
 }
@@ -62,12 +70,14 @@ func (p *prompter) processNextPacket() bool {
 		pc, empty = p.nextConnection()
 		p.lock.Unlock()
 		if pc != nil {
-			fmt.Println("GOT NON NIL")
+			fmt.Println("Got next pending connection...")
 		}
 		//fmt.Println("XXX: processNextPacket() loop; empty = ", empty, " / pc = ", pc)
 		if pc == nil && empty {
+			time.Sleep(100 * time.Millisecond)
 			return false
 		} else if pc == nil {
+			time.Sleep(100 * time.Millisecond)
 			continue
 		} else if pc != nil {
 			break
@@ -80,7 +90,6 @@ func (p *prompter) processNextPacket() bool {
 	}
 
 	pc.setPrompting(true)
-	fmt.Println("processConnection")
 	go p.processConnection(pc)
 	return true
 }
@@ -93,9 +102,48 @@ type PC2FDMapping struct {
 	prompter *prompter
 }
 
+func dumpPendingQueues() string {
+	result := ""
+	pctotal := 0
+
+	if gPrompter == nil {
+		return "Cannot query pending connections; no prompts have been issued yet!"
+	}
+
+	all_policies := make([]*Policy, 0)
+	gPrompter.lock.Lock()
+	defer gPrompter.lock.Unlock()
+
+	for _, policy := range gPrompter.policyMap {
+		all_policies = append(all_policies, policy)
+	}
+
+	result += fmt.Sprintf("Total policies: %d\n", len(all_policies))
+
+	for pind, policy := range all_policies {
+		policy.lock.Lock()
+
+		if len(policy.pendingQueue) > 0 {
+			result += fmt.Sprintf("  Policy %d of %d (%s): #pc = %d\n", pind+1,
+				len(all_policies), policy.application, len(policy.pendingQueue))
+
+			for pcind, pc := range policy.pendingQueue {
+				result += fmt.Sprintf("    %d: %s\n", pcind+1, pc.print())
+				pctotal++
+			}
+
+		}
+
+		policy.lock.Unlock()
+	}
+
+	result += "-----------------------------------\n"
+	result = fmt.Sprintf("Pending Queues / total pending connections = %d\n", pctotal) + result
+	return result
+}
+
 var PC2FDMap = map[string]PC2FDMapping{}
 var PC2FDMapLock = &sync.Mutex{}
-var PC2FDMapRunning = false
 
 func monitorPromptFDs(pc pendingConnection) {
 	guid := pc.getGUID()
@@ -104,7 +152,7 @@ func monitorPromptFDs(pc pendingConnection) {
 	fd := pc.procInfo().FD
 	prompter := pc.getPrompter()
 
-	fmt.Printf("ADD TO MONITOR: %v | %v / %v / %v\n", pc.policy().application, guid, pid, fd)
+	//fmt.Printf("ADD TO MONITOR: %v | %v / %v / %v\n", pc.policy().application, guid, pid, fd)
 
 	if pid == -1 || fd == -1 || prompter == nil {
 		log.Warning("Unexpected error condition occurred while adding socket fd to monitor")
@@ -119,16 +167,28 @@ func monitorPromptFDs(pc pendingConnection) {
 	return
 }
 
+func dumpMonitoredFDs() string {
+	PC2FDMapLock.Lock()
+	defer PC2FDMapLock.Unlock()
+
+	cnt := 1
+	result := fmt.Sprintf("Monitored FDs: %v total\n", len(PC2FDMap))
+	for guid, fdmon := range PC2FDMap {
+		result += fmt.Sprintf("%d: %s -> [inode=%v, fd=%d, fdpath=%s]\n", cnt, guid, fdmon.inode, fdmon.fd, fdmon.fdpath)
+		cnt++
+	}
+
+	result += "-----------------------------------\n"
+	return result
+}
+
 func monitorPromptFDLoop() {
-	fmt.Println("++++++++++= monitorPromptFDLoop()")
 
 	for true {
 		delete_guids := []string{}
 		PC2FDMapLock.Lock()
-		fmt.Println("++++ nentries = ", len(PC2FDMap))
 
 		for guid, fdmon := range PC2FDMap {
-			fmt.Println("ENTRY:", fdmon)
 
 			lsb, err := os.Stat(fdmon.fdpath)
 			if err != nil {
@@ -154,7 +214,10 @@ func monitorPromptFDLoop() {
 
 		}
 
+		if len(delete_guids) > 0 {
 			fmt.Println("guids to delete: ", delete_guids)
+		}
+
 		saved_mappings := []PC2FDMapping{}
 		for _, guid := range delete_guids {
 			saved_mappings = append(saved_mappings, PC2FDMap[guid])
@@ -164,9 +227,10 @@ func monitorPromptFDLoop() {
 		PC2FDMapLock.Unlock()
 
 		for _, mapping := range saved_mappings {
-			call := mapping.prompter.dbusObj.Call("com.subgraph.FirewallPrompt.RemovePrompt", 0, mapping.guid)
-			fmt.Println("DISPOSING CALL = ", call)
+			_ = mapping.prompter.dbusObj.Call("com.subgraph.FirewallPrompt.RemovePrompt", 0, mapping.guid)
+			// fmt.Println("DISPOSING CALL = ", call)
 			prompter := mapping.prompter
+			found := false
 
 			prompter.lock.Lock()
 
@@ -177,8 +241,9 @@ func monitorPromptFDLoop() {
 				for pcind < len(policy.pendingQueue) {
 
 					if policy.pendingQueue[pcind].getGUID() == mapping.guid {
-						fmt.Println("-------------- found guid to remove")
+						// fmt.Println("-------------- found guid to remove")
 						policy.pendingQueue = append(policy.pendingQueue[:pcind], policy.pendingQueue[pcind+1:]...)
+						found = true
 					} else {
 						pcind++
 					}
@@ -188,33 +253,27 @@ func monitorPromptFDLoop() {
 				policy.lock.Unlock()
 			}
 
+			if !found {
+				fmt.Println("Warning: FD monitor could not find pending connection to map to removed GUID: %s", mapping.guid)
+			}
+
 			prompter.lock.Unlock()
 		}
 
-		fmt.Println("++++++++++= monitorPromptFDLoop WAIT")
 		time.Sleep(5 * time.Second)
 	}
 
 }
 
+func init() {
+	go monitorPromptFDLoop()
+}
+
 func (p *prompter) processConnection(pc pendingConnection) {
 	var scope int32
 	var dres bool
 	var rule string
 
-	if !PC2FDMapRunning {
-		PC2FDMapLock.Lock()
-
-		if !PC2FDMapRunning {
-			PC2FDMapRunning = true
-			PC2FDMapLock.Unlock()
-			go monitorPromptFDLoop()
-		} else {
-			PC2FDMapLock.Unlock()
-		}
-
-	}
-
 	if pc.getPrompter() == nil {
 		pc.setPrompter(p)
 	}
@@ -338,10 +397,10 @@ func (p *prompter) nextConnection() (pendingConnection, bool) {
 	if len(p.policyQueue) == 0 {
 		return nil, true
 	}
-	fmt.Println("policy queue len = ", len(p.policyQueue))
+	//fmt.Println("policy queue len = ", len(p.policyQueue))
 
 	for pind < len(p.policyQueue) {
-		fmt.Printf("policy loop %d of %d\n", pind, len(p.policyQueue))
+		//fmt.Printf("policy loop %d of %d\n", pind, len(p.policyQueue))
 		//fmt.Printf("XXX: pind = %v of %v\n", pind, len(p.policyQueue))
 		policy := p.policyQueue[pind]
 		pc, qempty := policy.nextPending()
@@ -362,7 +421,11 @@ func (p *prompter) nextConnection() (pendingConnection, bool) {
 					pendingOther = append(pendingOther, r)
 				}
 			}
+
+			if len(pendingOnce) > 0 || len(pendingOther) > 0 {
 				fmt.Printf("# pending once = %d, other = %d, pc = %p / policy = %p\n", len(pendingOnce), len(pendingOther), pc, policy)
+			}
+
 			policy.rulesPending = pendingOther
 
 			// One time filters are all applied right here, at once.

sgfw/socks_server_chain.go

@@ -161,7 +161,8 @@ func (sc *pendingSocksConnection) setPrompting(val bool) {
 }
 
 func (sc *pendingSocksConnection) print() string {
-	return "socks connection"
+	return fmt.Sprintf("SOCKS5 %s {%v:%v -> %v:%v (%s)}",
+		sc.policy().path, sc.srcIP, sc.sourcePort, sc.destIP, sc.destPort, sc.hname)
 }
 
 func NewSocksChain(cfg *socksChainConfig, wg *sync.WaitGroup, fw *Firewall) *socksChain {

testfw/dbus.go

@@ -7,7 +7,6 @@ import (
 	"github.com/godbus/dbus"
 )
 
-
 const busName = "com.subgraph.FirewallTest"
 const objectPath = "/com/subgraph/FirewallTest"
 const interfaceName = "com.subgraph.FirewallTest"
@@ -58,10 +57,27 @@ func (ds *dbusServer) SGFWTestAlert(accepted int32, guid string, other string) (
 	return true, nil
 }
 
+func CallRunDebugCmd(d *dbusObjectP, cmd string, params string) string {
+	var dres string
+
+	fmt.Printf("> CallRunDebugCmd(cmd = %s, params = %s)\n", cmd, params)
+
+	call := d.Call("RunDebugCmd", 0,
+		cmd, params)
+
+	err := call.Store(&dres)
+	if err != nil {
+		fmt.Println("Error sending DBus RunDebugCmd() request:", err)
+		return ""
+	}
+
+	return dres
+}
+
 func CallAddTestVPC(d *dbusObjectP, proto string, srcip string, sport uint16, dstip string, dport uint16, hostname string) bool {
 	var dres bool
 
-	fmt.Printf("CallAddTestVPC(proto=%s, srcip=%s, sport=%u, dstip=%s, dport=%u, hostname=%s)\n",
+	fmt.Printf("> CallAddTestVPC(proto=%s, srcip=%s, sport=%u, dstip=%s, dport=%u, hostname=%s)\n",
 		proto, srcip, sport, dstip, dport, hostname)
 
 	call := d.Call("AddTestVPC", 0,

testfw/testfw.go

@@ -8,7 +8,6 @@ import (
 
 var dbuso *dbusObjectP
 
-
 func main() {
 	fmt.Println("Starting up test units...")
 
@@ -26,11 +25,26 @@ func main() {
 	res := CallAddTestVPC(dbuso, "udp", "10.0.0.1", 61921, "8.8.8.8", 53, "dnsthing.google.com")
 	fmt.Println("res =", res)
 
-
-	fmt.Println("Waiting until interrupted...")
+	fmt.Println("Looping until interrupted...")
 
 	for true {
-		time.Sleep(1 * time.Second)
+		result := CallRunDebugCmd(dbuso, "monitorfds", "")
+
+		if result == "" {
+			fmt.Println("Error: could not read monitored FDs information from SGFW.")
+		} else {
+			fmt.Println(result)
+		}
+
+		result = CallRunDebugCmd(dbuso, "listpending", "")
+
+		if result == "" {
+			fmt.Println("Error: could not read pending queue(s) information from SGFW.")
+		} else {
+			fmt.Println(result)
+		}
+
+		time.Sleep(5 * time.Second)
 	}
 
 }