diff --git a/src/croc/croc.go b/src/croc/croc.go index 141afb48..4b5dd24e 100644 --- a/src/croc/croc.go +++ b/src/croc/croc.go @@ -231,7 +231,7 @@ func New(ops Options) (c *Client, err error) { minBurstSize = int(uploadLimit) } c.limiter = rate.NewLimiter(rt, minBurstSize) - log.Debugf("Throttling Upload to %#v", c.limiter.Limit()) + log.Tracef("Throttling Upload to %#v", c.limiter.Limit()) } // initialize pake for recipient @@ -500,12 +500,12 @@ func (c *Client) sendCollectFiles(filesInfo []FileInfo) (err error) { } if fileInfo.Mode&os.ModeSymlink != 0 { - log.Debugf("%s is symlink", fileInfo.Name) + log.Tracef("%s is symlink", fileInfo.Name) c.FilesToTransfer[i].Symlink, err = os.Readlink(fullPath) if err != nil { - log.Debugf("error getting symlink: %s", err.Error()) + log.Tracef("error getting symlink: %s", err.Error()) } - log.Debugf("%+v", c.FilesToTransfer[i]) + log.Tracef("%+v", c.FilesToTransfer[i]) } if c.Options.HashAlgorithm == "" { @@ -513,16 +513,16 @@ func (c *Client) sendCollectFiles(filesInfo []FileInfo) (err error) { } c.FilesToTransfer[i].Hash, err = utils.HashFile(fullPath, c.Options.HashAlgorithm, fileInfo.Size > 1e7) - log.Debugf("hashed %s to %x using %s", fullPath, c.FilesToTransfer[i].Hash, c.Options.HashAlgorithm) + log.Tracef("hashed %s to %x using %s", fullPath, c.FilesToTransfer[i].Hash, c.Options.HashAlgorithm) totalFilesSize += fileInfo.Size if err != nil { return } - log.Debugf("file %d info: %+v", i, c.FilesToTransfer[i]) + log.Tracef("file %d info: %+v", i, c.FilesToTransfer[i]) fmt.Fprintf(os.Stderr, "\r ") fmt.Fprintf(os.Stderr, "\rSending %d files (%s)", i, utils.ByteCountDecimal(totalFilesSize)) } - log.Debugf("longestFilename: %+v", c.longestFilename) + log.Tracef("longestFilename: %+v", c.longestFilename) fname := fmt.Sprintf("%d files", len(c.FilesToTransfer)) folderName := fmt.Sprintf("%d folders", c.TotalNumberFolders) if len(c.FilesToTransfer) == 1 { @@ -590,42 +590,42 @@ func (c *Client) broadcastOnLocalNetwork(useipv6 bool) { } discoveries, err := peerdiscovery.Discover(settings) - log.Debugf("discoveries: %+v", discoveries) + log.Tracef("discoveries: %+v", discoveries) if err != nil { - log.Debug(err) + log.Trace(err) } } func (c *Client) transferOverLocalRelay(errchan chan<- error) { time.Sleep(500 * time.Millisecond) - log.Debug("establishing connection") + log.Trace("establishing connection") var banner string conn, banner, ipaddr, err := tcp.ConnectToTCPServer("127.0.0.1:"+c.Options.RelayPorts[0], c.Options.RelayPassword, c.Options.RoomName) - log.Debugf("banner: %s", banner) + log.Tracef("banner: %s", banner) if err != nil { err = fmt.Errorf("could not connect to 127.0.0.1:%s: %w", c.Options.RelayPorts[0], err) - log.Debug(err) + log.Trace(err) // not really an error because it will try to connect over the actual relay return } - log.Debugf("local connection established: %+v", conn) + log.Tracef("local connection established: %+v", conn) for { data, _ := conn.Receive() if bytes.Equal(data, handshakeRequest) { break } else if bytes.Equal(data, []byte{1}) { - log.Debug("got ping") + log.Trace("got ping") } else { - log.Debugf("instead of handshake got: %s", data) + log.Tracef("instead of handshake got: %s", data) } } c.conn[0] = conn - log.Debug("exchanged header message") + log.Trace("exchanged header message") c.Options.RelayAddress = "127.0.0.1" c.Options.RelayPorts = strings.Split(banner, ",") if c.Options.NoMultiplexing { - log.Debug("no multiplexing") + log.Trace("no multiplexing") c.Options.RelayPorts = []string{c.Options.RelayPorts[0]} } c.ExternalIP = ipaddr @@ -687,33 +687,33 @@ On the other computer run: continue } host, port, _ := net.SplitHostPort(address) - log.Debugf("host: '%s', port: '%s'", host, port) + log.Tracef("host: '%s', port: '%s'", host, port) // Default port to :9009 if port == "" { host = address port = models.DEFAULT_PORT } - log.Debugf("got host '%v' and port '%v'", host, port) + log.Tracef("got host '%v' and port '%v'", host, port) address = net.JoinHostPort(host, port) - log.Debugf("trying connection to %s", address) + log.Tracef("trying connection to %s", address) conn, banner, ipaddr, err = tcp.ConnectToTCPServer(address, c.Options.RelayPassword, c.Options.RoomName, durations[i]) if err == nil { c.Options.RelayAddress = address break } - log.Debugf("could not establish '%s'", address) + log.Tracef("could not establish '%s'", address) } if conn == nil && err == nil { err = fmt.Errorf("could not connect") } if err != nil { err = fmt.Errorf("could not connect to %s: %w", c.Options.RelayAddress, err) - log.Debug(err) + log.Trace(err) errchan <- err return } - log.Debugf("banner: %s", banner) - log.Debugf("connection established: %+v", conn) + log.Tracef("banner: %s", banner) + log.Tracef("connection established: %+v", conn) var kB []byte B, _ := pake.InitCurve([]byte(c.Options.SharedSecret[5:]), 1, c.Options.Curve) for { @@ -800,11 +800,11 @@ On the other computer run: c.conn[0] = conn c.Options.RelayPorts = strings.Split(banner, ",") if c.Options.NoMultiplexing { - log.Debug("no multiplexing") + log.Trace("no multiplexing") c.Options.RelayPorts = []string{c.Options.RelayPorts[0]} } c.ExternalIP = ipaddr - log.Debug("exchanged header message") + log.Trace("exchanged header message") errchan <- c.transfer() }() } @@ -814,7 +814,7 @@ On the other computer run: // return if no error return } else { - log.Debugf("error from errchan: %v", err) + log.Tracef("error from errchan: %v", err) if strings.Contains(err.Error(), "could not secure channel") { return err } @@ -844,18 +844,18 @@ func (c *Client) Receive() (err error) { if c.Options.IP != "" { // check ip version if strings.Count(c.Options.IP, ":") >= 2 { - log.Debug("assume ipv6") + log.Trace("assume ipv6") c.Options.RelayAddress6 = c.Options.IP } if strings.Contains(c.Options.IP, ".") { - log.Debug("assume ipv4") + log.Trace("assume ipv4") c.Options.RelayAddress = c.Options.IP } isIPset = true } if !c.Options.DisableLocal && !isIPset { - log.Debug("attempt to discover peers") + log.Trace("attempt to discover peers") var discoveries []peerdiscovery.Discovered var wgDiscovery sync.WaitGroup var dmux sync.Mutex @@ -895,14 +895,14 @@ func (c *Client) Receive() (err error) { wgDiscovery.Wait() if err == nil && len(discoveries) > 0 { - log.Debugf("all discoveries: %+v", discoveries) + log.Tracef("all discoveries: %+v", discoveries) for i := 0; i < len(discoveries); i++ { - log.Debugf("discovery %d has payload: %+v", i, discoveries[i]) + log.Tracef("discovery %d has payload: %+v", i, discoveries[i]) if !bytes.HasPrefix(discoveries[i].Payload, []byte("croc")) { - log.Debug("skipping discovery") + log.Trace("skipping discovery") continue } - log.Debug("switching to local") + log.Trace("switching to local") portToUse := string(bytes.TrimPrefix(discoveries[i].Payload, []byte("croc"))) if portToUse == "" { portToUse = models.DEFAULT_PORT @@ -910,19 +910,19 @@ func (c *Client) Receive() (err error) { address := net.JoinHostPort(discoveries[i].Address, portToUse) errPing := tcp.PingServer(address) if errPing == nil { - log.Debugf("successfully pinged '%s'", address) + log.Tracef("successfully pinged '%s'", address) c.Options.RelayAddress = address c.ExternalIPConnected = c.Options.RelayAddress c.Options.RelayAddress6 = "" usingLocal = true break } else { - log.Debugf("could not ping: %+v", errPing) + log.Tracef("could not ping: %+v", errPing) } } } - log.Debugf("discoveries: %+v", discoveries) - log.Debug("establishing connection") + log.Tracef("discoveries: %+v", discoveries) + log.Trace("establishing connection") } var banner string durations := []time.Duration{200 * time.Millisecond, 5 * time.Second} @@ -938,26 +938,26 @@ func (c *Client) Receive() (err error) { host = address port = models.DEFAULT_PORT } - log.Debugf("got host '%v' and port '%v'", host, port) + log.Tracef("got host '%v' and port '%v'", host, port) address = net.JoinHostPort(host, port) - log.Debugf("trying connection to %s", address) + log.Tracef("trying connection to %s", address) c.conn[0], banner, c.ExternalIP, err = tcp.ConnectToTCPServer(address, c.Options.RelayPassword, c.Options.RoomName, durations[i]) if err == nil { c.Options.RelayAddress = address break } - log.Debugf("could not establish '%s'", address) + log.Tracef("could not establish '%s'", address) } if err != nil { err = fmt.Errorf("could not connect to %s: %w", c.Options.RelayAddress, err) - log.Debug(err) + log.Trace(err) return } - log.Debugf("receiver connection established: %+v", c.conn[0]) - log.Debugf("banner: %s", banner) + log.Tracef("receiver connection established: %+v", c.conn[0]) + log.Tracef("banner: %s", banner) if c.Options.TestFlag { - log.Debugf("TEST FLAG ENABLED, TESTING LOCAL IPS") + log.Tracef("TEST FLAG ENABLED, TESTING LOCAL IPS") } if c.Options.TestFlag || (!usingLocal && !c.Options.DisableLocal && !isIPset) { // ask the sender for their local ips and port @@ -986,7 +986,7 @@ func (c *Client) Receive() (err error) { } err = json.Unmarshal(data, &dataMessage) if err != nil || dataMessage.Kind != "pake2" { - log.Debugf("data: %s", data) + log.Tracef("data: %s", data) return fmt.Errorf("dataMessage %s pake failed", ipRequest) } err = A.Update(dataMessage.Bytes) @@ -998,14 +998,14 @@ func (c *Client) Receive() (err error) { if err != nil { return } - log.Debugf("dataMessage kA: %x", kA) + log.Tracef("dataMessage kA: %x", kA) // secure ipRequest data, err = crypt.Encrypt([]byte(ipRequest), kA) if err != nil { return } - log.Debug("sending ips?") + log.Trace("sending ips?") if err = c.conn[0].Send(data); err != nil { log.Errorf("ips send error: %v", err) } @@ -1017,9 +1017,9 @@ func (c *Client) Receive() (err error) { if err != nil { return } - log.Debugf("ips data: %s", data) + log.Tracef("ips data: %s", data) if err = json.Unmarshal(data, &ips); err != nil { - log.Debugf("ips unmarshal error: %v", err) + log.Tracef("ips unmarshal error: %v", err) } return }() @@ -1029,32 +1029,32 @@ func (c *Client) Receive() (err error) { ips = ips[1:] for _, ip := range ips { ipv4Addr, ipv4Net, errNet := net.ParseCIDR(fmt.Sprintf("%s/24", ip)) - log.Debugf("ipv4Add4: %+v, ipv4Net: %+v, err: %+v", ipv4Addr, ipv4Net, errNet) + log.Tracef("ipv4Add4: %+v, ipv4Net: %+v, err: %+v", ipv4Addr, ipv4Net, errNet) localIps, _ := utils.GetLocalIPs() haveLocalIP := false for _, localIP := range localIps { localIPparsed := net.ParseIP(localIP) - log.Debugf("localIP: %+v, localIPparsed: %+v", localIP, localIPparsed) + log.Tracef("localIP: %+v, localIPparsed: %+v", localIP, localIPparsed) if ipv4Net.Contains(localIPparsed) { haveLocalIP = true - log.Debugf("ip: %+v is a local IP", ip) + log.Tracef("ip: %+v is a local IP", ip) break } } if !haveLocalIP { - log.Debugf("%s is not a local IP, skipping", ip) + log.Tracef("%s is not a local IP, skipping", ip) continue } serverTry := net.JoinHostPort(ip, port) conn, banner2, externalIP, errConn := tcp.ConnectToTCPServer(serverTry, c.Options.RelayPassword, c.Options.RoomName, 500*time.Millisecond) if errConn != nil { - log.Debug(errConn) - log.Debugf("could not connect to " + serverTry) + log.Trace(errConn) + log.Tracef("could not connect to " + serverTry) continue } - log.Debugf("local connection established to %s", serverTry) - log.Debugf("banner: %s", banner2) + log.Tracef("local connection established to %s", serverTry) + log.Tracef("banner: %s", banner2) // reset to the local port banner = banner2 c.Options.RelayAddress = serverTry @@ -1072,10 +1072,10 @@ func (c *Client) Receive() (err error) { } c.Options.RelayPorts = strings.Split(banner, ",") if c.Options.NoMultiplexing { - log.Debug("no multiplexing") + log.Trace("no multiplexing") c.Options.RelayPorts = []string{c.Options.RelayPorts[0]} } - log.Debug("exchanged header message") + log.Trace("exchanged header message") fmt.Fprintf(os.Stderr, "\rsecuring channel...") err = c.transfer() if err == nil { @@ -1093,7 +1093,7 @@ func (c *Client) transfer() (err error) { c.quit = make(chan bool) // if recipient, initialize with sending pake information - log.Debug("ready") + log.Trace("ready") if !c.Options.IsSender && !c.Step1ChannelSecured { err = message.Send(c.conn[0], c.Key, message.Message{ Type: message.TypePAKE, @@ -1111,7 +1111,7 @@ func (c *Client) transfer() (err error) { var done bool data, err = c.conn[0].Receive() if err != nil { - log.Debugf("got error receiving: %v", err) + log.Tracef("got error receiving: %v", err) if !c.Step1ChannelSecured { err = fmt.Errorf("could not secure channel") } @@ -1119,8 +1119,8 @@ func (c *Client) transfer() (err error) { } done, err = c.processMessage(data) if err != nil { - log.Debugf("data: %s", data) - log.Debugf("got error processing: %v", err) + log.Tracef("data: %s", data) + log.Tracef("got error processing: %v", err) break } if done { @@ -1130,7 +1130,7 @@ func (c *Client) transfer() (err error) { // purge errors that come from successful transfer if c.SuccessfulTransfer { if err != nil { - log.Debugf("purging error: %s", err) + log.Tracef("purging error: %s", err) } err = nil } @@ -1148,7 +1148,7 @@ func (c *Client) transfer() (err error) { if file.TempFile { utils.UnzipDirectory(".", file.Name) os.Remove(file.Name) - log.Debugf("Removing %s\n", file.Name) + log.Tracef("Removing %s\n", file.Name) } } } @@ -1158,7 +1158,7 @@ func (c *Client) transfer() (err error) { c.FilesToTransfer[c.FilesToTransferCurrentNum].FolderRemote, c.FilesToTransfer[c.FilesToTransferCurrentNum].Name, ) - log.Debugf("pathToFile: %s", pathToFile) + log.Tracef("pathToFile: %s", pathToFile) // close if not closed already if !c.CurrentFileIsClosed { c.CurrentFile.Close() @@ -1170,11 +1170,11 @@ func (c *Client) transfer() (err error) { fmt.Fprint(os.Stderr, "\n") } if err != nil && strings.Contains(err.Error(), "pake not successful") { - log.Debugf("pake error: %s", err.Error()) + log.Tracef("pake error: %s", err.Error()) err = fmt.Errorf("password mismatch") } if err != nil && strings.Contains(err.Error(), "unexpected end of JSON input") { - log.Debugf("error: %s", err.Error()) + log.Tracef("error: %s", err.Error()) err = fmt.Errorf("room (secure channel) not ready, maybe peer disconnected") } return @@ -1206,7 +1206,7 @@ func (c *Client) processMessageFileInfo(m message.Message) (done bool, err error var senderInfo SenderInfo err = json.Unmarshal(m.Bytes, &senderInfo) if err != nil { - log.Debug(err) + log.Trace(err) return } c.Options.SendingText = senderInfo.SendingText @@ -1242,9 +1242,9 @@ func (c *Client) processMessageFileInfo(m message.Message) (done bool, err error if c.Options.HashAlgorithm == "" { c.Options.HashAlgorithm = "xxhash" } - log.Debugf("using hash algorithm: %s", c.Options.HashAlgorithm) + log.Tracef("using hash algorithm: %s", c.Options.HashAlgorithm) if c.Options.NoCompress { - log.Debug("disabling compression") + log.Trace("disabling compression") } if c.Options.SendingText { c.Options.Stdout = true @@ -1311,7 +1311,7 @@ func (c *Client) processMessageFileInfo(m message.Message) (done bool, err error } else { isEmpty, _ := isEmptyFolder(c.EmptyFoldersToTransfer[i].FolderRemote) if !isEmpty { - log.Debug("asking to overwrite") + log.Trace("asking to overwrite") prompt := fmt.Sprintf("\n%s already has some content in it. \nDo you want"+ " to overwrite it with an empty folder? (y/N) ", c.EmptyFoldersToTransfer[i].FolderRemote) choice := strings.ToLower(utils.GetInput(prompt)) @@ -1337,18 +1337,18 @@ func (c *Client) processMessageFileInfo(m message.Message) (done bool, err error err = errStopTransfer } } - log.Debug(c.FilesToTransfer) + log.Trace(c.FilesToTransfer) c.Step2FileInfoTransferred = true return } func (c *Client) processMessagePake(m message.Message) (err error) { - log.Debug("received pake payload") + log.Trace("received pake payload") var salt []byte if c.Options.IsSender { // initialize curve based on the recipient's choice - log.Debugf("using curve %s", string(m.Bytes2)) + log.Tracef("using curve %s", string(m.Bytes2)) c.Pake, err = pake.InitCurve([]byte(c.Options.SharedSecret[5:]), 1, string(m.Bytes2)) if err != nil { log.Error(err) @@ -1362,13 +1362,13 @@ func (c *Client) processMessagePake(m message.Message) (err error) { } // generate salt and send it back to recipient - log.Debug("generating salt") + log.Trace("generating salt") salt = make([]byte, 8) if _, rerr := rand.Read(salt); err != nil { log.Errorf("can't generate random numbers: %v", rerr) return } - log.Debug("sender sending pake+salt") + log.Trace("sender sending pake+salt") err = message.Send(c.conn[0], c.Key, message.Message{ Type: message.TypePAKE, Bytes: c.Pake.Bytes(), @@ -1390,13 +1390,13 @@ func (c *Client) processMessagePake(m message.Message) (err error) { if err != nil { return err } - log.Debugf("generated key = %+x with salt %x", c.Key, salt) + log.Tracef("generated key = %+x with salt %x", c.Key, salt) // connects to the other ports of the server for transfer var wg sync.WaitGroup wg.Add(len(c.Options.RelayPorts)) for i := 0; i < len(c.Options.RelayPorts); i++ { - log.Debugf("port: [%s]", c.Options.RelayPorts[i]) + log.Tracef("port: [%s]", c.Options.RelayPorts[i]) go func(j int) { defer wg.Done() var host string @@ -1410,7 +1410,7 @@ func (c *Client) processMessagePake(m message.Message) (err error) { } } server := net.JoinHostPort(host, c.Options.RelayPorts[j]) - log.Debugf("connecting to %s", server) + log.Tracef("connecting to %s", server) c.conn[j+1], _, _, err = tcp.ConnectToTCPServer( server, c.Options.RelayPassword, @@ -1419,7 +1419,7 @@ func (c *Client) processMessagePake(m message.Message) (err error) { if err != nil { panic(err) } - log.Debugf("connected to %s", server) + log.Tracef("connected to %s", server) if !c.Options.IsSender { go c.receiveData(j) } @@ -1428,7 +1428,7 @@ func (c *Client) processMessagePake(m message.Message) (err error) { wg.Wait() if !c.Options.IsSender { - log.Debug("sending external IP") + log.Trace("sending external IP") err = message.Send(c.conn[0], c.Key, message.Message{ Type: message.TypeExternalIP, Message: c.ExternalIP, @@ -1439,7 +1439,7 @@ func (c *Client) processMessagePake(m message.Message) (err error) { } func (c *Client) processExternalIP(m message.Message) (done bool, err error) { - log.Debugf("received external IP: %+v", m) + log.Tracef("received external IP: %+v", m) if c.Options.IsSender { err = message.Send(c.conn[0], c.Key, message.Message{ Type: message.TypeExternalIP, @@ -1453,7 +1453,7 @@ func (c *Client) processExternalIP(m message.Message) (done bool, err error) { // it can be preset by the local relay c.ExternalIPConnected = m.Message } - log.Debugf("connected as %s -> %s", c.ExternalIP, c.ExternalIPConnected) + log.Tracef("connected as %s -> %s", c.ExternalIP, c.ExternalIPConnected) c.Step1ChannelSecured = true return } @@ -1462,7 +1462,7 @@ func (c *Client) processMessage(payload []byte) (done bool, err error) { m, err := message.Decode(c.Key, payload) if err != nil { err = fmt.Errorf("problem with decoding: %w", err) - log.Debug(err) + log.Trace(err) return } @@ -1477,6 +1477,7 @@ func (c *Client) processMessage(payload []byte) (done bool, err error) { switch m.Type { case message.TypeFinished: + log.Trace("received message.TypeFinished") err = message.Send(c.conn[0], c.Key, message.Message{ Type: message.TypeFinished, }) @@ -1484,12 +1485,14 @@ func (c *Client) processMessage(payload []byte) (done bool, err error) { c.SuccessfulTransfer = true return case message.TypePAKE: + log.Trace("received message.TypePAKE") err = c.processMessagePake(m) if err != nil { err = fmt.Errorf("pake not successful: %w", err) - log.Debug(err) + log.Trace(err) } case message.TypeExternalIP: + log.Trace("received message.TypeExternalIP") done, err = c.processExternalIP(m) case message.TypeError: // c.spinner.Stop() @@ -1497,8 +1500,10 @@ func (c *Client) processMessage(payload []byte) (done bool, err error) { err = fmt.Errorf("peer error: %s", m.Message) return true, err case message.TypeFileInfo: + log.Trace("received message.TypeFileInfo") done, err = c.processMessageFileInfo(m) case message.TypeRecipientReady: + log.Trace("received message.TypeRecipientReady") var remoteFile RemoteFileRequest err = json.Unmarshal(m.Bytes, &remoteFile) if err != nil { @@ -1507,7 +1512,7 @@ func (c *Client) processMessage(payload []byte) (done bool, err error) { c.FilesToTransferCurrentNum = remoteFile.FilesToTransferCurrentNum c.CurrentFileChunkRanges = remoteFile.CurrentFileChunkRanges c.CurrentFileChunks = utils.ChunkRangesToChunks(c.CurrentFileChunkRanges) - log.Debugf("current file chunks: %+v", c.CurrentFileChunks) + log.Tracef("current file chunks: %+v", c.CurrentFileChunks) c.mutex.Lock() c.chunkMap = make(map[uint64]struct{}) for _, chunk := range c.CurrentFileChunks { @@ -1529,25 +1534,25 @@ func (c *Client) processMessage(payload []byte) (done bool, err error) { } } case message.TypeCloseSender: + log.Trace("received message.TypeCloseSender") c.bar.Finish() - log.Debug("close-sender received...") c.Step4FileTransferred = false c.Step3RecipientRequestFile = false - log.Debug("sending close-recipient") err = message.Send(c.conn[0], c.Key, message.Message{ Type: message.TypeCloseRecipient, }) case message.TypeCloseRecipient: + log.Trace("received message.TypeCloseRecipient") c.Step4FileTransferred = false c.Step3RecipientRequestFile = false } if err != nil { - log.Debugf("got error from processing message: %v", err) + log.Tracef("got error from processing message: %v", err) return } err = c.updateState() if err != nil { - log.Debugf("got error from updating state: %v", err) + log.Tracef("got error from updating state: %v", err) return } return @@ -1586,7 +1591,7 @@ func (c *Client) updateIfSenderChannelSecured() (err error) { func (c *Client) recipientInitializeFile() (err error) { // start initiating the process to receive a new file - log.Debugf("working on file %d", c.FilesToTransferCurrentNum) + log.Tracef("working on file %d", c.FilesToTransferCurrentNum) // recipient sets the file pathToFile := path.Join( @@ -1646,7 +1651,7 @@ func (c *Client) recipientInitializeFile() (err error) { func (c *Client) recipientGetFileReady(finished bool) (err error) { if finished { // TODO: do the last finishing stuff - log.Debug("finished") + log.Trace("finished") err = message.Send(c.conn[0], c.Key, message.Message{ Type: message.TypeFinished, }) @@ -1671,7 +1676,7 @@ func (c *Client) recipientGetFileReady(finished bool) (err error) { FilesToTransferCurrentNum: c.FilesToTransferCurrentNum, MachineID: machID, }) - log.Debug("converting to chunk range") + log.Trace("converting to chunk range") c.CurrentFileChunks = utils.ChunkRangesToChunks(c.CurrentFileChunkRanges) if !finished { @@ -1679,7 +1684,7 @@ func (c *Client) recipientGetFileReady(finished bool) (err error) { c.setBar() } - log.Debugf("sending recipient ready with %d chunks", len(c.CurrentFileChunks)) + log.Tracef("sending recipient ready with %d chunks", len(c.CurrentFileChunks)) err = message.Send(c.conn[0], c.Key, message.Message{ Type: message.TypeRecipientReady, Bytes: bRequest, @@ -1692,7 +1697,7 @@ func (c *Client) recipientGetFileReady(finished bool) (err error) { } func (c *Client) createEmptyFileAndFinish(fileInfo FileInfo, i int) (err error) { - log.Debugf("touching file with folder / name") + log.Tracef("touching file with folder / name") if !utils.Exists(fileInfo.FolderRemote) { err = os.MkdirAll(fileInfo.FolderRemote, os.ModePerm) if err != nil { @@ -1702,7 +1707,7 @@ func (c *Client) createEmptyFileAndFinish(fileInfo FileInfo, i int) (err error) } pathToFile := path.Join(fileInfo.FolderRemote, fileInfo.Name) if fileInfo.Symlink != "" { - log.Debug("creating symlink") + log.Trace("creating symlink") // remove symlink if it exists if _, errExists := os.Lstat(pathToFile); errExists == nil { os.Remove(pathToFile) @@ -1761,7 +1766,7 @@ func (c *Client) updateIfRecipientHasFileInfo() (err error) { if i < c.FilesToTransferCurrentNum { continue } - log.Debugf("checking %+v", fileInfo) + log.Tracef("checking %+v", fileInfo) recipientFileInfo, errRecipientFile := os.Lstat(path.Join(fileInfo.FolderRemote, fileInfo.Name)) var errHash error var fileHash []byte @@ -1778,10 +1783,10 @@ func (c *Client) updateIfRecipientHasFileInfo() (err error) { } continue } - log.Debugf("%s %+x %+x %+v", fileInfo.Name, fileHash, fileInfo.Hash, errHash) + log.Tracef("%s %+x %+x %+v", fileInfo.Name, fileHash, fileInfo.Hash, errHash) if !bytes.Equal(fileHash, fileInfo.Hash) { - log.Debugf("hashed %s to %x using %s", fileInfo.Name, fileHash, c.Options.HashAlgorithm) - log.Debugf("hashes are not equal %x != %x", fileHash, fileInfo.Hash) + log.Tracef("hashed %s to %x using %s", fileInfo.Name, fileHash, c.Options.HashAlgorithm) + log.Tracef("hashes are not equal %x != %x", fileHash, fileInfo.Hash) if errHash == nil && !c.Options.Overwrite && errRecipientFile == nil && !strings.HasPrefix(fileInfo.Name, "croc-stdin-") && !c.Options.SendingText { missingChunks := utils.ChunkRangesToChunks(utils.MissingChunks( @@ -1791,7 +1796,7 @@ func (c *Client) updateIfRecipientHasFileInfo() (err error) { )) percentDone := 100 - float64(len(missingChunks)*models.TCP_BUFFER_SIZE/2)/float64(fileInfo.Size)*100 - log.Debug("asking to overwrite") + log.Trace("asking to overwrite") prompt := fmt.Sprintf("\nOverwrite '%s'? (y/N) (use --overwrite to omit) ", path.Join(fileInfo.FolderRemote, fileInfo.Name)) if percentDone < 99 { prompt = fmt.Sprintf("\nResume '%s' (%2.1f%%)? (y/N) (use --overwrite to omit) ", path.Join(fileInfo.FolderRemote, fileInfo.Name), percentDone) @@ -1803,11 +1808,11 @@ func (c *Client) updateIfRecipientHasFileInfo() (err error) { } } } else { - log.Debugf("hashes are equal %x == %x", fileHash, fileInfo.Hash) + log.Tracef("hashes are equal %x == %x", fileHash, fileInfo.Hash) } if errHash != nil { // probably can't find, its okay - log.Debug(errHash) + log.Trace(errHash) } if errHash != nil || !bytes.Equal(fileHash, fileInfo.Hash) { finished = false @@ -1846,7 +1851,7 @@ func (c *Client) updateState() (err error) { } if c.Options.IsSender && c.Step3RecipientRequestFile && !c.Step4FileTransferred { - log.Debug("start sending data!") + log.Trace("start sending data!") if !c.firstSend { fmt.Fprintf(os.Stderr, "\nSending (->%s)\n", c.ExternalIPConnected) @@ -1881,7 +1886,7 @@ func (c *Client) updateState() (err error) { c.setBar() c.TotalSent = 0 c.CurrentFileIsClosed = false - log.Debug("beginning sending comms") + log.Trace("beginning sending comms") pathToFile := path.Join( c.FilesToTransfer[c.FilesToTransferCurrentNum].FolderSource, c.FilesToTransfer[c.FilesToTransferCurrentNum].Name, @@ -1892,7 +1897,7 @@ func (c *Client) updateState() (err error) { return } for i := 0; i < len(c.Options.RelayPorts); i++ { - log.Debugf("starting sending over comm %d", i) + // log.Tracef("starting sending over comm %d", i) go c.sendData(i) } } @@ -1927,9 +1932,9 @@ func (c *Client) setBar() { byteToDo := int64(len(c.CurrentFileChunks) * models.TCP_BUFFER_SIZE / 2) if byteToDo > 0 { bytesDone := c.FilesToTransfer[c.FilesToTransferCurrentNum].Size - byteToDo - log.Debug(byteToDo) - log.Debug(c.FilesToTransfer[c.FilesToTransferCurrentNum].Size) - log.Debug(bytesDone) + log.Trace(byteToDo) + log.Trace(c.FilesToTransfer[c.FilesToTransferCurrentNum].Size) + log.Trace(bytesDone) if bytesDone > 0 { c.bar.Add64(bytesDone) } @@ -1973,15 +1978,15 @@ func (c *Client) receiveData(i int) { c.bar.Add(len(data[8:])) c.TotalSent += int64(len(data[8:])) c.TotalChunksTransferred++ - // log.Debug(len(c.CurrentFileChunks), c.TotalChunksTransferred, c.TotalSent, c.FilesToTransfer[c.FilesToTransferCurrentNum].Size) + // log.Trace(len(c.CurrentFileChunks), c.TotalChunksTransferred, c.TotalSent, c.FilesToTransfer[c.FilesToTransferCurrentNum].Size) if !c.CurrentFileIsClosed && (c.TotalChunksTransferred == len(c.CurrentFileChunks) || c.TotalSent == c.FilesToTransfer[c.FilesToTransferCurrentNum].Size) { c.CurrentFileIsClosed = true - log.Debug("finished receiving!") + log.Trace("finished receiving!") if err = c.CurrentFile.Close(); err != nil { - log.Debugf("error closing %s: %v", c.CurrentFile.Name(), err) + log.Tracef("error closing %s: %v", c.CurrentFile.Name(), err) } else { - log.Debugf("Successful closing %s", c.CurrentFile.Name()) + log.Tracef("Successful closing %s", c.CurrentFile.Name()) } if c.Options.Stdout || c.Options.SendingText { pathToFile := path.Join( @@ -1991,7 +1996,7 @@ func (c *Client) receiveData(i int) { b, _ := os.ReadFile(pathToFile) fmt.Print(string(b)) } - log.Debug("sending close-sender") + log.Trace("sending close-sender") err = message.Send(c.conn[0], c.Key, message.Message{ Type: message.TypeCloseSender, }) @@ -2005,10 +2010,10 @@ func (c *Client) receiveData(i int) { func (c *Client) sendData(i int) { defer func() { - log.Debugf("finished with %d", i) + // log.Tracef("finished with %d", i) c.numfinished++ if c.numfinished == len(c.Options.RelayPorts) { - log.Debug("closing file") + log.Trace("closing file") if err := c.fread.Close(); err != nil { log.Errorf("error closing file: %v", err) } @@ -2027,7 +2032,7 @@ func (c *Client) sendData(i int) { n, errRead = c.fread.ReadAt(data, readingPos) if c.limiter != nil { r := c.limiter.ReserveN(time.Now(), n) - log.Debugf("Limiting Upload for %d", r.Delay()) + log.Tracef("Limiting Upload for %d", r.Delay()) time.Sleep(r.Delay()) } if n > 0 { @@ -2043,7 +2048,7 @@ func (c *Client) sendData(i int) { } c.mutex.Unlock() if usableChunk { - // log.Debugf("sending chunk %d", pos) + // log.Tracef("sending chunk %d", pos) posByte := make([]byte, 8) binary.LittleEndian.PutUint64(posByte, pos) var err error diff --git a/src/message/message.go b/src/message/message.go index 3ee0f266..0675e8f9 100644 --- a/src/message/message.go +++ b/src/message/message.go @@ -55,10 +55,10 @@ func Encode(key []byte, m Message) (b []byte, err error) { } b = compress.Compress(b) if key != nil { - log.Debugf("writing %s message (encrypted)", m.Type) + log.Tracef("writing %s message (encrypted)", m.Type) b, err = crypt.Encrypt(b, key) } else { - log.Debugf("writing %s message (unencrypted)", m.Type) + log.Tracef("writing %s message (unencrypted)", m.Type) } return } @@ -75,9 +75,9 @@ func Decode(key []byte, b []byte) (m Message, err error) { err = json.Unmarshal(b, &m) if err == nil { if key != nil { - log.Debugf("read %s message (encrypted)", m.Type) + log.Tracef("read %s message (encrypted)", m.Type) } else { - log.Debugf("read %s message (unencrypted)", m.Type) + log.Tracef("read %s message (unencrypted)", m.Type) } } return diff --git a/src/tcp/tcp.go b/src/tcp/tcp.go index c6bf67ed..f46bdf09 100644 --- a/src/tcp/tcp.go +++ b/src/tcp/tcp.go @@ -76,7 +76,7 @@ func Run(debugLevel, host, port, password string, banner ...string) (err error) func (s *server) start() (err error) { log.SetLevel(s.debugLevel) - log.Debugf("starting with password '%s'", s.password) + log.Tracef("starting with password '%s'", s.password) s.rooms.Lock() s.rooms.rooms = make(map[string]roomInfo) s.rooms.Unlock() @@ -126,42 +126,42 @@ func (s *server) run() (err error) { if err != nil { return fmt.Errorf("problem accepting connection: %w", err) } - log.Debugf("client %s connected", connection.RemoteAddr().String()) + log.Tracef("client %s connected", connection.RemoteAddr().String()) go func(port string, connection net.Conn) { c := comm.New(connection) room, errCommunication := s.clientCommunication(port, c) - log.Debugf("room: %+v", room) - log.Debugf("err: %+v", errCommunication) + log.Tracef("room: %+v", room) + log.Tracef("err: %+v", errCommunication) if errCommunication != nil { - log.Debugf("relay-%s: %s", connection.RemoteAddr().String(), errCommunication.Error()) + log.Tracef("relay-%s: %s", connection.RemoteAddr().String(), errCommunication.Error()) connection.Close() return } if room == pingRoom { - log.Debugf("got ping") + log.Tracef("got ping") connection.Close() return } for { // check connection - log.Debugf("checking connection of room %s for %+v", room, c) + log.Tracef("checking connection of room %s for %+v", room, c) deleteIt := false s.rooms.Lock() if _, ok := s.rooms.rooms[room]; !ok { - log.Debug("room is gone") + log.Trace("room is gone") s.rooms.Unlock() return } - log.Debugf("room: %+v", s.rooms.rooms[room]) + log.Tracef("room: %+v", s.rooms.rooms[room]) if s.rooms.rooms[room].first != nil && s.rooms.rooms[room].second != nil { - log.Debug("rooms ready") + log.Trace("rooms ready") s.rooms.Unlock() break } else { if s.rooms.rooms[room].first != nil { errSend := s.rooms.rooms[room].first.Send([]byte{1}) if errSend != nil { - log.Debug(errSend) + log.Trace(errSend) deleteIt = true } } @@ -195,18 +195,18 @@ func (s *server) deleteOldRooms() { for _, room := range roomsToDelete { s.deleteRoom(room) - log.Debugf("room cleaned up: %s", room) + log.Tracef("room cleaned up: %s", room) } case <-s.stopRoomCleanup: ticker.Stop() - log.Debug("room cleanup stopped") + log.Trace("room cleanup stopped") return } } } func (s *server) stopRoomDeletion() { - log.Debug("stop room cleanup fired") + log.Trace("stop room cleanup fired") s.stopRoomCleanup <- struct{}{} } @@ -222,10 +222,10 @@ func (s *server) clientCommunication(port string, c *comm.Comm) (room string, er if err != nil { return } - log.Debugf("Abytes: %s", Abytes) + log.Tracef("Abytes: %s", Abytes) if bytes.Equal(Abytes, []byte("ping")) { room = pingRoom - log.Debug("sending back pong") + log.Trace("sending back pong") c.Send([]byte("pong")) return } @@ -241,7 +241,7 @@ func (s *server) clientCommunication(port string, c *comm.Comm) (room string, er if err != nil { return } - log.Debugf("strongkey: %x", strongKey) + log.Tracef("strongkey: %x", strongKey) // receive salt salt, err := c.Receive() @@ -253,7 +253,7 @@ func (s *server) clientCommunication(port string, c *comm.Comm) (room string, er return } - log.Debugf("waiting for password") + log.Tracef("waiting for password") passwordBytesEnc, err := c.Receive() if err != nil { return @@ -276,7 +276,7 @@ func (s *server) clientCommunication(port string, c *comm.Comm) (room string, er if len(banner) == 0 { banner = "ok" } - log.Debugf("sending '%s'", banner) + log.Tracef("sending '%s'", banner) bSend, err := crypt.Encrypt([]byte(banner+"|||"+c.Connection().RemoteAddr().String()), strongKeyForEncryption) if err != nil { return @@ -287,7 +287,7 @@ func (s *server) clientCommunication(port string, c *comm.Comm) (room string, er } // wait for client to tell me which room they want - log.Debug("waiting for answer") + log.Trace("waiting for answer") enc, err := c.Receive() if err != nil { return @@ -318,7 +318,7 @@ func (s *server) clientCommunication(port string, c *comm.Comm) (room string, er s.deleteRoom(room) return } - log.Debugf("room %s has 1", room) + log.Tracef("room %s has 1", room) return } if s.rooms.rooms[room].full { @@ -334,7 +334,7 @@ func (s *server) clientCommunication(port string, c *comm.Comm) (room string, er } return } - log.Debugf("room %s has 2", room) + log.Tracef("room %s has 2", room) s.rooms.rooms[room] = roomInfo{ first: s.rooms.rooms[room].first, second: c, @@ -350,10 +350,10 @@ func (s *server) clientCommunication(port string, c *comm.Comm) (room string, er // start piping go func(com1, com2 *comm.Comm, wg *sync.WaitGroup) { - log.Debug("starting pipes") + log.Trace("starting pipes") pipe(com1.Connection(), com2.Connection()) wg.Done() - log.Debug("done piping") + log.Trace("done piping") }(otherConnection, c, &wg) // tell the sender everything is ready @@ -379,7 +379,7 @@ func (s *server) deleteRoom(room string) { if _, ok := s.rooms.rooms[room]; !ok { return } - log.Debugf("deleting room: %s", room) + log.Tracef("deleting room: %s", room) if s.rooms.rooms[room].first != nil { s.rooms.rooms[room].first.Close() } @@ -410,12 +410,12 @@ func chanFromConn(conn net.Conn) chan []byte { c <- res } if err != nil { - log.Debug(err) + log.Trace(err) c <- nil break } } - log.Debug("exiting") + log.Trace("exiting") }() return c @@ -449,20 +449,20 @@ func pipe(conn1 net.Conn, conn2 net.Conn) { } func PingServer(address string) (err error) { - log.Debugf("pinging %s", address) + log.Tracef("pinging %s", address) c, err := comm.NewConnection(address, 300*time.Millisecond) if err != nil { - log.Debug(err) + log.Trace(err) return } err = c.Send([]byte("ping")) if err != nil { - log.Debug(err) + log.Trace(err) return } b, err := c.Receive() if err != nil { - log.Debug(err) + log.Trace(err) return } if bytes.Equal(b, []byte("pong")) { @@ -480,106 +480,106 @@ func ConnectToTCPServer(address, password, room string, timelimit ...time.Durati c, err = comm.NewConnection(address) } if err != nil { - log.Debug(err) + log.Trace(err) return } // get PAKE connection with server to establish strong key to transfer info A, err := pake.InitCurve(weakKey, 0, "siec") if err != nil { - log.Debug(err) + log.Trace(err) return } err = c.Send(A.Bytes()) if err != nil { - log.Debug(err) + log.Trace(err) return } Bbytes, err := c.Receive() if err != nil { - log.Debug(err) + log.Trace(err) return } err = A.Update(Bbytes) if err != nil { - log.Debug(err) + log.Trace(err) return } strongKey, err := A.SessionKey() if err != nil { - log.Debug(err) + log.Trace(err) return } - log.Debugf("strong key: %x", strongKey) + log.Tracef("strong key: %x", strongKey) strongKeyForEncryption, salt, err := crypt.New(strongKey, nil) if err != nil { - log.Debug(err) + log.Trace(err) return } // send salt err = c.Send(salt) if err != nil { - log.Debug(err) + log.Trace(err) return } - log.Debug("sending password") + log.Trace("sending password") bSend, err := crypt.Encrypt([]byte(password), strongKeyForEncryption) if err != nil { - log.Debug(err) + log.Trace(err) return } err = c.Send(bSend) if err != nil { - log.Debug(err) + log.Trace(err) return } - log.Debug("waiting for first ok") + log.Trace("waiting for first ok") enc, err := c.Receive() if err != nil { - log.Debug(err) + log.Trace(err) return } data, err := crypt.Decrypt(enc, strongKeyForEncryption) if err != nil { - log.Debug(err) + log.Trace(err) return } if !strings.Contains(string(data), "|||") { err = fmt.Errorf("bad response: %s", string(data)) - log.Debug(err) + log.Trace(err) return } banner = strings.Split(string(data), "|||")[0] ipaddr = strings.Split(string(data), "|||")[1] - log.Debugf("sending room; %s", room) + log.Tracef("sending room; %s", room) bSend, err = crypt.Encrypt([]byte(room), strongKeyForEncryption) if err != nil { - log.Debug(err) + log.Trace(err) return } err = c.Send(bSend) if err != nil { - log.Debug(err) + log.Trace(err) return } - log.Debug("waiting for room confirmation") + log.Trace("waiting for room confirmation") enc, err = c.Receive() if err != nil { - log.Debug(err) + log.Trace(err) return } data, err = crypt.Decrypt(enc, strongKeyForEncryption) if err != nil { - log.Debug(err) + log.Trace(err) return } if !bytes.Equal(data, []byte("ok")) { err = fmt.Errorf("got bad response: %s", data) - log.Debug(err) + log.Trace(err) return } - log.Debug("all set") + log.Trace("all set") return }