From 85d7d60d76aeac4a710ab9ad3fd0facfcbb42274 Mon Sep 17 00:00:00 2001 From: Stephen Watt Date: Wed, 4 Oct 2017 00:27:06 -0400 Subject: [PATCH] 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 | 14 +++++ sgfw/policy.go | 4 +- sgfw/prompt.go | 119 ++++++++++++++++++++++++++++--------- sgfw/socks_server_chain.go | 3 +- testfw/dbus.go | 22 ++++++- testfw/testfw.go | 22 +++++-- 6 files changed, 146 insertions(+), 38 deletions(-) diff --git a/sgfw/dbus.go b/sgfw/dbus.go index 0f7a2ad..714eedc 100644 --- a/sgfw/dbus.go +++ b/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) diff --git a/sgfw/policy.go b/sgfw/policy.go index 5bfb77f..33974fa 100644 --- a/sgfw/policy.go +++ b/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) { diff --git a/sgfw/prompt.go b/sgfw/prompt.go index 55c378c..8c31f64 100644 --- a/sgfw/prompt.go +++ b/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() { } - fmt.Println("guids to delete: ", delete_guids) + 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) } } - fmt.Printf("# pending once = %d, other = %d, pc = %p / policy = %p\n", len(pendingOnce), len(pendingOther), pc, policy) + + 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. diff --git a/sgfw/socks_server_chain.go b/sgfw/socks_server_chain.go index e4fbf58..1236959 100644 --- a/sgfw/socks_server_chain.go +++ b/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 { diff --git a/testfw/dbus.go b/testfw/dbus.go index 9f2fba2..9f96a0d 100644 --- a/testfw/dbus.go +++ b/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" @@ -26,7 +25,7 @@ func newDbusObjectAdd() (*dbusObjectP, error) { } type dbusServer struct { - conn *dbus.Conn + conn *dbus.Conn } func newDbusServer() (*dbusServer, error) { @@ -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, diff --git a/testfw/testfw.go b/testfw/testfw.go index d972f38..40e1fd5 100644 --- a/testfw/testfw.go +++ b/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) } }