diff --git a/README.md b/README.md index 8ab451f1..2ca002e8 100644 --- a/README.md +++ b/README.md @@ -35,10 +35,9 @@ source ~/.bashrc Download the latest release from GitHub: - ### 2. Create Configuration File -Create a `config.yml` file in the same directory as your binary +Create a `config.yml` file in your base directory (default: `~/.supernode/config.yml`): ```yaml # Supernode Configuration @@ -156,13 +155,13 @@ The supernode binary supports the following command-line flags: | Flag | Short | Description | Value Type | Example | Default | |------|-------|-------------|------------|---------|---------| -| `--config` | `-c` | Path to configuration file | String | `-c /path/to/config.yml` | `config.yml` in current directory | +| `--config` | `-c` | Path to configuration file | String | `-c /path/to/config.yml` | `config.yml` in basedir (`~/.supernode/config.yml`) | | `--basedir` | `-d` | Base directory for data storage | String | `-d /custom/path` | `~/.supernode` | ### Usage Examples ```bash -# Use default config.yml in current directory, with ~/.supernode as basedir +# Use default config.yml in basedir (~/.supernode/config.yml), with ~/.supernode as basedir supernode start # Use custom config file @@ -181,11 +180,10 @@ supernode start -c /etc/supernode/config.yml -d /opt/supernode If you use custom flags (`--config` or `--basedir`) for key management operations, you **MUST** use the same flags for ALL subsequent commands, including the `start` command. Otherwise, your configuration will break and keys will not be found. - ### Additional Important Notes: - Make sure you have sufficient balance in your Lumera account to broadcast transactions - The P2P port (4445) should not be changed from the default - Your `key_name` in the config must match the name you used when creating the key - Your `identity` in the config must match the address generated for your key -- Ensure your Lumera validator node is running and accessible at the configured gRPC address +- Ensure your Lumera validator node is running and accessible at the configured gRPC address \ No newline at end of file diff --git a/p2p/kademlia/bootstrap.go b/p2p/kademlia/bootstrap.go index f9da31d8..6dcd71c2 100644 --- a/p2p/kademlia/bootstrap.go +++ b/p2p/kademlia/bootstrap.go @@ -12,7 +12,7 @@ import ( "github.com/LumeraProtocol/supernode/pkg/errors" "github.com/LumeraProtocol/supernode/pkg/utils" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" ltc "github.com/LumeraProtocol/supernode/pkg/net/credentials" ) @@ -65,9 +65,11 @@ func (s *DHT) parseNode(extP2P string, selfAddr string) (*Node, error) { // For system testing, use port+1 if SYSTEM_TEST=true if os.Getenv("SYSTEM_TEST") == "true" { port = uint16(portNum) + 1 - log.P2P().WithField("original_port", portNum). - WithField("adjusted_port", port). - Info("Using port+1 for system testing") + logtrace.Info(context.Background(), "Using port+1 for system testing", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "original_port": portNum, + "adjusted_port": port, + }) } else { // For normal P2P operation, always use the default port port = defaultNetworkPort @@ -108,7 +110,10 @@ func (s *DHT) setBootstrapNodesFromConfigVar(ctx context.Context, bootstrapNodes }) } s.options.BootstrapNodes = nodes - log.P2P().WithContext(ctx).WithField("bootstrap_nodes", nodes).Info("Bootstrap nodes set from config var") + logtrace.Info(ctx, "Bootstrap nodes set from config var", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "bootstrap_nodes": nodes, + }) return nil } @@ -158,15 +163,22 @@ func (s *DHT) ConfigureBootstrapNodes(ctx context.Context, bootstrapNodes string } if latestIP == "" { - log.P2P().WithContext(ctx).WithField("supernode", supernode.SupernodeAccount).Warn("No valid IP address found for supernode") + logtrace.Warn(ctx, "No valid IP address found for supernode", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "supernode": supernode.SupernodeAccount, + }) continue } // Parse the node from the IP address node, err := s.parseNode(latestIP, selfAddress) if err != nil { - log.P2P().WithContext(ctx).WithError(err).WithField("address", latestIP).WithField("supernode", supernode.SupernodeAccount). - Warn("Skip Bad Bootstrap Address") + logtrace.Warn(ctx, "Skip Bad Bootstrap Address", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + "address": latestIP, + "supernode": supernode.SupernodeAccount, + }) continue } @@ -185,13 +197,19 @@ func (s *DHT) ConfigureBootstrapNodes(ctx context.Context, bootstrapNodes string } if len(boostrapNodes) == 0 { - log.WithContext(ctx).Error("unable to fetch bootstrap IP addresses. No valid supernodes found.") + logtrace.Error(ctx, "unable to fetch bootstrap IP addresses. No valid supernodes found.", logtrace.Fields{ + logtrace.FieldModule: "p2p", + }) return nil } for _, node := range boostrapNodes { - log.WithContext(ctx).WithFields(log.Fields{"bootstap_ip": node.IP, "bootstrap_port": node.Port, "node_id": string(node.ID)}). - Info("adding p2p bootstrap node") + logtrace.Info(ctx, "adding p2p bootstrap node", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "bootstap_ip": node.IP, + "bootstrap_port": node.Port, + "node_id": string(node.ID), + }) } s.options.BootstrapNodes = append(s.options.BootstrapNodes, boostrapNodes...) @@ -221,7 +239,10 @@ func (s *DHT) Bootstrap(ctx context.Context, bootstrapNodes string) error { addr := fmt.Sprintf("%s:%v", node.IP, node.Port) if _, err := s.cache.Get(addr); err == nil { - log.P2P().WithContext(ctx).WithField("addr", addr).Info("skip bad p2p boostrap addr") + logtrace.Info(ctx, "skip bad p2p boostrap addr", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "addr": addr, + }) continue } @@ -245,20 +266,32 @@ func (s *DHT) Bootstrap(ctx context.Context, bootstrapNodes string) error { // So if bootstrap failed, should try to connect to node again for next bootstrap retry // s.cache.SetWithExpiry(addr, []byte("true"), badAddrExpiryHours*time.Hour) - log.P2P().WithContext(ctx).WithError(err).Error("network call failed, sleeping 3 seconds") + logtrace.Error(ctx, "network call failed, sleeping 3 seconds", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + }) time.Sleep(5 * time.Second) continue } - log.P2P().WithContext(ctx).Debugf("ping response: %v", response.String()) + logtrace.Debug(ctx, "ping response", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "response": response.String(), + }) // add the node to the route table - log.P2P().WithContext(ctx).WithField("sender-id", string(response.Sender.ID)). - WithField("sender-ip", string(response.Sender.IP)). - WithField("sender-port", response.Sender.Port).Debug("add-node params") + logtrace.Debug(ctx, "add-node params", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "sender-id": string(response.Sender.ID), + "sender-ip": string(response.Sender.IP), + "sender-port": response.Sender.Port, + }) if len(response.Sender.ID) != len(s.ht.self.ID) { - log.P2P().WithContext(ctx).WithField("sender-id", string(response.Sender.ID)). - WithField("self-id", string(s.ht.self.ID)).Error("self ID && sender ID len don't match") + logtrace.Error(ctx, "self ID && sender ID len don't match", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "sender-id": string(response.Sender.ID), + "self-id": string(s.ht.self.ID), + }) continue } @@ -277,7 +310,10 @@ func (s *DHT) Bootstrap(ctx context.Context, bootstrapNodes string) error { if s.ht.totalCount() > 0 { // iterative find node from the nodes if _, err := s.iterate(ctx, IterateFindNode, s.ht.self.ID, nil, 0); err != nil { - log.P2P().WithContext(ctx).WithError(err).Error("iterative find node failed") + logtrace.Error(ctx, "iterative find node failed", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + }) return err } } else { @@ -291,12 +327,18 @@ func (s *DHT) Bootstrap(ctx context.Context, bootstrapNodes string) error { func (s *DHT) retryBootstrap(ctx context.Context, bootstrapNodes string) { if err := s.ConfigureBootstrapNodes(ctx, bootstrapNodes); err != nil { - log.P2P().WithContext(ctx).WithError(err).Error("retry failed to get bootstap ip") + logtrace.Error(ctx, "retry failed to get bootstap ip", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + }) return } // join the kademlia network if bootstrap nodes is set if err := s.Bootstrap(ctx, bootstrapNodes); err != nil { - log.P2P().WithContext(ctx).WithError(err).Error("retry failed - bootstrap the node.") + logtrace.Error(ctx, "retry failed - bootstrap the node.", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + }) } } diff --git a/p2p/kademlia/dht.go b/p2p/kademlia/dht.go index f6121bb8..ab2546ce 100644 --- a/p2p/kademlia/dht.go +++ b/p2p/kademlia/dht.go @@ -16,7 +16,7 @@ import ( "github.com/LumeraProtocol/lumera/x/lumeraid/securekeyx" "github.com/LumeraProtocol/supernode/pkg/errors" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" "github.com/LumeraProtocol/supernode/pkg/lumera" ltc "github.com/LumeraProtocol/supernode/pkg/net/credentials" "github.com/LumeraProtocol/supernode/pkg/storage" @@ -216,12 +216,18 @@ func (s *DHT) Store(ctx context.Context, data []byte, typ int) (string, error) { retKey := base58.Encode(key) // store the key to queries storage if err := s.retryStore(ctx, key, data, typ); err != nil { - log.WithContext(ctx).WithError(err).Error("queries data store failure after retries") + logtrace.Error(ctx, "Local data store failure after retries", logtrace.Fields{ + logtrace.FieldModule: "dht", + logtrace.FieldError: err.Error(), + }) return "", fmt.Errorf("retry store data to queries storage: %v", err) } if _, err := s.iterate(ctx, IterateStore, key, data, typ); err != nil { - log.WithContext(ctx).WithError(err).Error("iterate data store failure") + logtrace.Error(ctx, "Iterate data store failure", logtrace.Fields{ + logtrace.FieldModule: "dht", + logtrace.FieldError: err.Error(), + }) return "", fmt.Errorf("iterative store data: %v", err) } @@ -230,17 +236,27 @@ func (s *DHT) Store(ctx context.Context, data []byte, typ int) (string, error) { // StoreBatch will store a batch of values with their Blake3 hash as the key func (s *DHT) StoreBatch(ctx context.Context, values [][]byte, typ int, taskID string) error { - log.WithContext(ctx).WithField("taskID", taskID).WithField("records", len(values)).Info("store db batch begin") + logtrace.Info(ctx, "Store DB batch begin", logtrace.Fields{ + logtrace.FieldModule: "dht", + logtrace.FieldTaskID: taskID, + "records": len(values), + }) if err := s.store.StoreBatch(ctx, values, typ, true); err != nil { return fmt.Errorf("store batch: %v", err) } - log.WithContext(ctx).WithField("taskID", taskID).Info("store db batch done,store network batch begin") + logtrace.Info(ctx, "Store DB batch done, store network batch begin", logtrace.Fields{ + logtrace.FieldModule: "dht", + logtrace.FieldTaskID: taskID, + }) if err := s.IterateBatchStore(ctx, values, typ, taskID); err != nil { return fmt.Errorf("iterate batch store: %v", err) } - log.WithContext(ctx).WithField("taskID", taskID).Info("store network batch workers done") + logtrace.Info(ctx, "Store network batch workers done", logtrace.Fields{ + logtrace.FieldModule: "dht", + logtrace.FieldTaskID: taskID, + }) return nil } @@ -265,7 +281,11 @@ func (s *DHT) Retrieve(ctx context.Context, key string, localOnly ...bool) ([]by if err == nil && len(value) > 0 { return value, nil } else if err != nil { - log.WithContext(ctx).WithField("db_key", dbKey).WithError(err).Error("error retrieving key") + logtrace.Error(ctx, "Error retrieving key from local storage", logtrace.Fields{ + logtrace.FieldModule: "dht", + "db_key": dbKey, + logtrace.FieldError: err.Error(), + }) } // if queries only option is set, do not search just return error @@ -279,9 +299,16 @@ func (s *DHT) Retrieve(ctx context.Context, key string, localOnly ...bool) ([]by return nil, errors.Errorf("retrieve from peer: %w", err) } if len(peerValue) > 0 { - log.WithContext(ctx).WithField("key", dbKey).WithField("data len", len(peerValue)).Debug("Not found locally, retrieved from other nodes") + logtrace.Debug(ctx, "Not found locally, retrieved from other nodes", logtrace.Fields{ + logtrace.FieldModule: "dht", + "key": dbKey, + "data_len": len(peerValue), + }) } else { - log.WithContext(ctx).WithField("key", dbKey).Debug("Not found locally, not found in other nodes") + logtrace.Debug(ctx, "Not found locally, not found in other nodes", logtrace.Fields{ + logtrace.FieldModule: "dht", + "key": dbKey, + }) } return peerValue, nil @@ -347,7 +374,11 @@ func (s *DHT) GetValueFromNode(ctx context.Context, target []byte, n *Node) ([]b response, err := s.network.Call(cctx, request, false) if err != nil { - log.P2P().WithContext(ctx).WithError(err).Debugf("network call request %s failed", request.String()) + logtrace.Debug(ctx, "Network call request failed", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + "request": request.String(), + }) return nil, fmt.Errorf("network call request %s failed: %w", request.String(), err) } @@ -385,7 +416,11 @@ func (s *DHT) doMultiWorkers(ctx context.Context, iterativeType int, target []by // update the running goroutines number++ - log.P2P().WithContext(ctx).Debugf("start work %v for node: %s", iterativeType, node.String()) + logtrace.Debug(ctx, "Start work for node", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "iterate_type": iterativeType, + "node": node.String(), + }) wg.Add(1) // send and receive message concurrently @@ -408,7 +443,11 @@ func (s *DHT) doMultiWorkers(ctx context.Context, iterativeType int, target []by // send the request and receive the response response, err := s.network.Call(ctx, request, false) if err != nil { - log.P2P().WithContext(ctx).WithError(err).Debugf("network call request %s failed", request.String()) + logtrace.Debug(ctx, "Network call request failed", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + "request": request.String(), + }) // node is unreachable, remove the node //removedNodes = append(removedNodes, receiver) return @@ -441,15 +480,19 @@ func (s *DHT) fetchAndAddLocalKeys(ctx context.Context, hexKeys []string, result batchHexKeys := hexKeys[start:end] - log.WithFields(log.Fields{ - "batchSize": len(batchHexKeys), - "totalKeys": len(hexKeys), - }).Info("Processing batch of local keys") + logtrace.Info(ctx, "Processing batch of local keys", logtrace.Fields{ + logtrace.FieldModule: "dht", + "batch_size": len(batchHexKeys), + "total_keys": len(hexKeys), + }) // Retrieve values for the current batch of local keys localValues, _, batchErr := s.store.RetrieveBatchValues(ctx, batchHexKeys, false) if batchErr != nil { - log.WithField("error", batchErr).Error("Failed to retrieve batch values") + logtrace.Error(ctx, "Failed to retrieve batch values", logtrace.Fields{ + logtrace.FieldModule: "dht", + logtrace.FieldError: batchErr.Error(), + }) err = fmt.Errorf("retrieve batch values (local): %v", batchErr) continue // Optionally continue with next batch or return depending on use case } @@ -488,7 +531,12 @@ func (s *DHT) BatchRetrieve(ctx context.Context, keys []string, required int32, k, err := hex.DecodeString(hexKey) if err != nil { - log.WithContext(ctx).WithError(err).WithField("key", hexKey).WithField("txid", txID).Error("failed to decode hex key in resMap.Range") + logtrace.Error(ctx, "Failed to decode hex key in resMap.Range", logtrace.Fields{ + logtrace.FieldModule: "dht", + "key": hexKey, + "txid": txID, + logtrace.FieldError: err.Error(), + }) return true } @@ -521,7 +569,11 @@ func (s *DHT) BatchRetrieve(ctx context.Context, keys []string, required int32, hashes[i] = decoded hexKeys[i] = hex.EncodeToString(decoded) } - log.WithContext(ctx).WithField("self", self.String()).WithField("txid", txID).Info("populated keys and hashes") + logtrace.Info(ctx, "Populated keys and hashes", logtrace.Fields{ + logtrace.FieldModule: "dht", + "self": self.String(), + "txid": txID, + }) // Add nodes from route table to known nodes map for _, node := range s.ht.nodes() { @@ -540,7 +592,10 @@ func (s *DHT) BatchRetrieve(ctx context.Context, keys []string, required int32, s.addKnownNodes(ctx, top6.Nodes, knownNodes) } - log.WithContext(ctx).WithField("txid", txID).Info("closest contacts populated, fetching local keys now") + logtrace.Info(ctx, "Closest contacts populated, fetching local keys now", logtrace.Fields{ + logtrace.FieldModule: "dht", + "txid": txID, + }) // remove self from the map delete(knownNodes, string(self.ID)) @@ -549,7 +604,11 @@ func (s *DHT) BatchRetrieve(ctx context.Context, keys []string, required int32, if err != nil { return nil, fmt.Errorf("fetch and add local keys: %v", err) } - log.WithContext(ctx).WithField("txid", txID).WithField("local-foundCount", foundLocalCount).Info("batch find values count") + logtrace.Info(ctx, "Batch find values count", logtrace.Fields{ + logtrace.FieldModule: "dht", + "txid": txID, + "local_found_count": foundLocalCount, + }) if foundLocalCount >= required { return result, nil @@ -566,7 +625,11 @@ func (s *DHT) BatchRetrieve(ctx context.Context, keys []string, required int32, gctx, cancel := context.WithCancel(ctx) defer cancel() - log.WithContext(ctx).WithField("txid", txID).WithField("parallel batches", parallelBatches).Debug("begin iterate batch get values") + logtrace.Debug(ctx, "Begin iterate batch get values", logtrace.Fields{ + logtrace.FieldModule: "dht", + "txid": txID, + "parallel_batches": parallelBatches, + }) // Process in batches for start := 0; start < len(keys); start += batchSize { end := start + batchSize @@ -587,7 +650,10 @@ func (s *DHT) BatchRetrieve(ctx context.Context, keys []string, required int32, } wg.Wait() // Wait for all goroutines to finish - log.WithContext(ctx).WithField("txid", txID).Info("iterate batch get values workers done") + logtrace.Info(ctx, "Iterate batch get values workers done", logtrace.Fields{ + logtrace.FieldModule: "dht", + "txid": txID, + }) return result, nil } @@ -619,7 +685,11 @@ func (s *DHT) processBatch(ctx context.Context, batchKeys []string, batchHexKeys // Iterate through the network to get the values for the current batch foundCount, newClosestContacts, batchErr := s.iterateBatchGetValues(ctx, knownNodes, batchKeys, batchHexKeys, fetchMap, resMap, required, foundLocalCount+atomic.LoadInt32(networkFound)) if batchErr != nil { - log.WithContext(ctx).WithError(batchErr).WithField("txid", txID).Error("iterate batch get values failed") + logtrace.Error(ctx, "Iterate batch get values failed", logtrace.Fields{ + logtrace.FieldModule: "dht", + "txid": txID, + logtrace.FieldError: batchErr.Error(), + }) } // Update the global counter for found values @@ -640,12 +710,21 @@ func (s *DHT) processBatch(ctx context.Context, batchKeys []string, batchHexKeys } if globalClosestContacts[key] == nil || globalClosestContacts[key].Nodes == nil { - log.WithContext(ctx).WithField("key", key).Warn("global contacts list doesn't have the key") + logtrace.Warn(ctx, "Global contacts list doesn't have the key", logtrace.Fields{ + logtrace.FieldModule: "dht", + "key": key, + }) continue } if !haveAllNodes(nodesList.Nodes, globalClosestContacts[key].Nodes) { - log.WithContext(ctx).WithField("key", key).WithField("have", nodesList.String()).WithField("task-id", txID).WithField("got", globalClosestContacts[key].String()).Info("global closest contacts list changed in fetch!") + logtrace.Info(ctx, "Global closest contacts list changed in fetch", logtrace.Fields{ + logtrace.FieldModule: "dht", + "key": key, + "have": nodesList.String(), + "task_id": txID, + "got": globalClosestContacts[key].String(), + }) changed = true } @@ -662,7 +741,11 @@ func (s *DHT) processBatch(ctx context.Context, batchKeys []string, batchHexKeys } if i == maxIterations-1 { - log.WithContext(ctx).WithField("iter", i).WithField("task-id", txID).Warn("max iterations reached, still top 6 list was changed") + logtrace.Warn(ctx, "Max iterations reached, still top 6 list was changed", logtrace.Fields{ + logtrace.FieldModule: "dht", + "iter": i, + "task_id": txID, + }) } } } @@ -681,7 +764,10 @@ func (s *DHT) iterateBatchGetValues(ctx context.Context, nodes map[string]*Node, defer cancel() for nodeID, node := range nodes { if s.ignorelist.Banned(node) { - log.WithContext(ctx).WithField("node", node.String()).Info("Ignore banned node in iterate batch get values") + logtrace.Info(ctx, "Ignore banned node in iterate batch get values", logtrace.Fields{ + logtrace.FieldModule: "dht", + "node": node.String(), + }) continue } @@ -743,17 +829,28 @@ func (s *DHT) iterateBatchGetValues(ctx context.Context, nodes map[string]*Node, wg.Wait() - log.WithContext(ctx).WithField("found-count", atomic.LoadInt32(&foundCount)).Info("iterate batch get values done") + logtrace.Info(ctx, "Iterate batch get values done", logtrace.Fields{ + logtrace.FieldModule: "dht", + "found_count": atomic.LoadInt32(&foundCount), + }) if firstErr != nil { - log.WithContext(ctx).WithError(firstErr).WithField("found-count", atomic.LoadInt32(&foundCount)).Error("encountered error in iterate batch get values") + logtrace.Error(ctx, "Encountered error in iterate batch get values", logtrace.Fields{ + logtrace.FieldModule: "dht", + "found_count": atomic.LoadInt32(&foundCount), + logtrace.FieldError: firstErr.Error(), + }) } for _, closestNodes := range contactsMap { for key, nodes := range closestNodes { comparator, err := hex.DecodeString(key) if err != nil { - log.WithContext(ctx).WithError(err).WithField("key", key).Error("failed to decode hex key in closestNodes.Range") + logtrace.Error(ctx, "Failed to decode hex key in closestNodes.Range", logtrace.Fields{ + logtrace.FieldModule: "dht", + "key": key, + logtrace.FieldError: err.Error(), + }) return 0, nil, err } bkey := base58.Encode(comparator) @@ -803,9 +900,9 @@ func (s *DHT) iterate(ctx context.Context, iterativeType int, target []byte, dat return s.iterateFindValue(ctx, iterativeType, target) } - val := ctx.Value(log.TaskIDKey) + // Get task ID from context taskID := "" - if val != nil { + if val := ctx.Value(logtrace.CorrelationIDKey); val != nil { taskID = fmt.Sprintf("%v", val) } @@ -815,13 +912,23 @@ func (s *DHT) iterate(ctx context.Context, iterativeType int, target []byte, dat // find the closest contacts for the target node from queries route tables nl, _ := s.ht.closestContacts(Alpha, target, igList) if len(igList) > 0 { - log.P2P().WithContext(ctx).WithField("nodes", nl.String()).WithField("ignored", s.ignorelist.String()).Info("closest contacts") + logtrace.Info(ctx, "Closest contacts", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "nodes": nl.String(), + "ignored": s.ignorelist.String(), + }) } // if no closer node, stop search if nl.Len() == 0 { return nil, nil } - log.P2P().WithContext(ctx).WithField("task_id", taskID).Debugf("type: %v, target: %v, nodes: %v", iterativeType, sKey, nl.String()) + logtrace.Debug(ctx, "Iterate start", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "task_id": taskID, + "type": iterativeType, + "target": sKey, + "nodes": nl.String(), + }) // keep the closer node closestNode := nl.Nodes[0] @@ -829,7 +936,10 @@ func (s *DHT) iterate(ctx context.Context, iterativeType int, target []byte, dat if iterativeType == IterateFindNode { hashedTargetID, _ := utils.Blake3Hash(target) bucket := s.ht.bucketIndex(s.ht.self.HashedID, hashedTargetID) - log.P2P().WithContext(ctx).Debugf("bucket for target: %v", sKey) + logtrace.Debug(ctx, "Bucket for target", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "target": sKey, + }) // reset the refresh time for the bucket s.ht.resetRefreshTime(bucket) @@ -850,14 +960,20 @@ func (s *DHT) iterate(ctx context.Context, iterativeType int, target []byte, dat // Set a maximum number of iterations to prevent indefinite looping maxIterations := 5 // Adjust the maximum iterations as needed - log.P2P().WithContext(ctx).WithField("task_id", taskID).WithField("key", sKey).Debug("begin iteration") + logtrace.Debug(ctx, "Begin iteration", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "task_id": taskID, + "key": sKey, + }) for i := 0; i < maxIterations; i++ { select { case <-ctx.Done(): return nil, fmt.Errorf("iterate cancelled: %w", ctx.Err()) case <-timeout: - log.P2P().WithContext(ctx).Debug("iteration timed out") + logtrace.Debug(ctx, "Iteration timed out", logtrace.Fields{ + logtrace.FieldModule: "p2p", + }) return nil, nil default: // Do the requests concurrently @@ -878,13 +994,20 @@ func (s *DHT) iterate(ctx context.Context, iterativeType int, target []byte, dat } default: - log.WithContext(ctx).WithField("type", response.MessageType).Error("unknown message type") + logtrace.Error(ctx, "Unknown message type", logtrace.Fields{ + logtrace.FieldModule: "dht", + "type": response.MessageType, + }) } } // Stop search if no more nodes to contact if !searchRest && len(nl.Nodes) == 0 { - log.P2P().WithContext(ctx).WithField("task_id", taskID).WithField("key", sKey).Info("search stopped") + logtrace.Info(ctx, "Search stopped", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "task_id": taskID, + "key": sKey, + }) return nil, nil } @@ -892,7 +1015,12 @@ func (s *DHT) iterate(ctx context.Context, iterativeType int, target []byte, dat nl.Comparator = target nl.Sort() - log.P2P().WithContext(ctx).Debugf("id: %v, iterate %d, sorted nodes: %v", base58.Encode(s.ht.self.ID), iterativeType, nl.String()) + logtrace.Debug(ctx, "Iterate sorted nodes", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "id": base58.Encode(s.ht.self.ID), + "iterate": iterativeType, + "nodes": nl.String(), + }) switch iterativeType { case IterateFindNode: @@ -911,7 +1039,12 @@ func (s *DHT) iterate(ctx context.Context, iterativeType int, target []byte, dat case IterateStore: // Store the value to the node list if err := s.storeToAlphaNodes(ctx, nl, data, typ, taskID); err != nil { - log.WithContext(ctx).WithField("task_id", taskID).WithField("key", sKey).Errorf("could not store value to remaining network: %v", err) + logtrace.Error(ctx, "Could not store value to remaining network", logtrace.Fields{ + logtrace.FieldModule: "dht", + "task_id": taskID, + "key": sKey, + logtrace.FieldError: err.Error(), + }) } return nil, nil @@ -919,7 +1052,11 @@ func (s *DHT) iterate(ctx context.Context, iterativeType int, target []byte, dat } } - log.P2P().WithContext(ctx).WithField("task_id", taskID).WithField("key", sKey).Info("finish iteration without results") + logtrace.Info(ctx, "Finish iteration without results", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "task_id": taskID, + "key": sKey, + }) return nil, nil } @@ -935,7 +1072,9 @@ func (s *DHT) handleResponses(ctx context.Context, responses <-chan *Message, nl v, ok := response.Data.(*FindValueResponse) if ok { if v.Status.Result == ResultOk && len(v.Value) > 0 { - log.P2P().WithContext(ctx).Debug("iterate found value from network") + logtrace.Debug(ctx, "Iterate found value from network", logtrace.Fields{ + logtrace.FieldModule: "p2p", + }) return nl, v.Value } else if len(v.Closest) > 0 { nl.AddNodes(v.Closest) @@ -948,10 +1087,9 @@ func (s *DHT) handleResponses(ctx context.Context, responses <-chan *Message, nl } func (s *DHT) iterateFindValue(ctx context.Context, iterativeType int, target []byte) ([]byte, error) { - // If task_id is available, use it for logging - This helps with debugging - val := ctx.Value(log.TaskIDKey) + // Get task ID from context taskID := "" - if val != nil { + if val := ctx.Value(logtrace.CorrelationIDKey); val != nil { taskID = fmt.Sprintf("%v", val) } @@ -964,7 +1102,11 @@ func (s *DHT) iterateFindValue(ctx context.Context, iterativeType int, target [] // nl will have the closest nodes to the target value, it will ignore the nodes in igList nl, _ := s.ht.closestContacts(Alpha, target, igList) if len(igList) > 0 { - log.P2P().WithContext(ctx).WithField("nodes", nl.String()).WithField("ignored", s.ignorelist.String()).Info("closest contacts") + logtrace.Info(ctx, "Closest contacts", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "nodes": nl.String(), + "ignored": s.ignorelist.String(), + }) } // if no nodes are found, return - this is a corner case and should not happen in practice @@ -975,21 +1117,41 @@ func (s *DHT) iterateFindValue(ctx context.Context, iterativeType int, target [] searchRest := false // keep track of contacted nodes so that we don't hit them again contacted := make(map[string]bool) - log.P2P().WithContext(ctx).WithField("task_id", taskID).WithField("key", sKey).Debug("begin iteration") + logtrace.Debug(ctx, "Begin iteration", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "task_id": taskID, + "key": sKey, + }) var closestNode *Node var iterationCount int for iterationCount = 0; iterationCount < maxIterations; iterationCount++ { - log.P2P().WithContext(ctx).WithField("task_id", taskID).WithField("nl", nl.Len()).Debugf("begin find value - target: %v , nodes: %v", sKey, nl.String()) + logtrace.Debug(ctx, "Begin find value", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "task_id": taskID, + "nl": nl.Len(), + "target": sKey, + "nodes": nl.String(), + }) if nl.Len() == 0 { - log.P2P().WithContext(ctx).WithField("task_id", taskID).WithField("key", sKey).WithField("iteration count", iterationCount).Error("nodes list length is 0") + logtrace.Error(ctx, "Nodes list length is 0", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "task_id": taskID, + "key": sKey, + "iteration_count": iterationCount, + }) return nil, nil } // if the closest node is the same as the last iteration and we don't want to search rest of nodes, we are done if !searchRest && (closestNode != nil && bytes.Equal(nl.Nodes[0].ID, closestNode.ID)) { - log.P2P().WithContext(ctx).WithField("task_id", taskID).WithField("key", sKey).WithField("iteration count", iterationCount).Debug("closest node is the same as the last iteration") + logtrace.Debug(ctx, "Closest node is the same as the last iteration", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "task_id": taskID, + "key": sKey, + "iteration_count": iterationCount, + }) return nil, nil } @@ -1003,10 +1165,20 @@ func (s *DHT) iterateFindValue(ctx context.Context, iterativeType int, target [] nl.Sort() - log.P2P().WithContext(ctx).WithField("task_id", taskID).WithField("key", sKey).Debugf("iteration: %v, nodes: %v", iterationCount, nl.Len()) + logtrace.Debug(ctx, "Iteration progress", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "task_id": taskID, + "key": sKey, + "iteration": iterationCount, + "nodes": nl.Len(), + }) } - log.P2P().WithContext(ctx).WithField("task_id", taskID).WithField("key", sKey).Info("finished iterations without results") + logtrace.Info(ctx, "Finished iterations without results", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "task_id": taskID, + "key": sKey, + }) return nil, nil } @@ -1048,7 +1220,9 @@ func (s *DHT) sendStoreData(ctx context.Context, n *Node, request *StoreDataRequ func (s *DHT) addNode(ctx context.Context, node *Node) *Node { // ensure this is not itself address if bytes.Equal(node.ID, s.ht.self.ID) { - log.P2P().WithContext(ctx).Debug("trying to add itself") + logtrace.Debug(ctx, "Trying to add itself", logtrace.Fields{ + logtrace.FieldModule: "p2p", + }) return nil } node.SetHashedID() @@ -1056,7 +1230,12 @@ func (s *DHT) addNode(ctx context.Context, node *Node) *Node { index := s.ht.bucketIndex(s.ht.self.HashedID, node.HashedID) if err := s.updateReplicationNode(ctx, node.ID, node.IP, node.Port, true); err != nil { - log.P2P().WithContext(ctx).WithField("node-id", string(node.ID)).WithField("node-ip", node.IP).WithError(err).Error("update replication node failed") + logtrace.Error(ctx, "Update replication node failed", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "node_id": string(node.ID), + "node_ip": node.IP, + logtrace.FieldError: err.Error(), + }) } if s.ht.hasBucketNode(index, node.ID) { @@ -1141,7 +1320,10 @@ func (s *DHT) LocalStore(ctx context.Context, key string, data []byte) (string, // store the key to queries storage if err := s.retryStore(ctx, decoded, data, 0); err != nil { - log.WithContext(ctx).WithError(err).Error("queries data store failure after retries") + logtrace.Error(ctx, "Local data store failure after retries", logtrace.Fields{ + logtrace.FieldModule: "dht", + logtrace.FieldError: err.Error(), + }) return "", fmt.Errorf("retry store data to queries storage: %v", err) } @@ -1161,15 +1343,26 @@ func (s *DHT) storeToAlphaNodes(ctx context.Context, nl *NodeList, data []byte, } go func(n *Node) { - logEntry := log.P2P().WithContext(ctx).WithField("node", n).WithField("task_id", taskID) request := &StoreDataRequest{Data: data, Type: typ} response, err := s.sendStoreData(ctx, n, request) if err != nil { - logEntry.WithError(err).Error("send store data failed") + errorFields := logtrace.Fields{ + logtrace.FieldModule: "p2p", + "node": n.String(), + "task_id": taskID, + logtrace.FieldError: err.Error(), + } + logtrace.Error(ctx, "Send store data failed", errorFields) alphaCh <- false } else if response.Status.Result != ResultOk { - logEntry.WithError(errors.New(response.Status.ErrMsg)).Error("reply store data failed") + errorFields := logtrace.Fields{ + logtrace.FieldModule: "p2p", + "node": n.String(), + "task_id": taskID, + logtrace.FieldError: response.Status.ErrMsg, + } + logtrace.Error(ctx, "Reply store data failed", errorFields) alphaCh <- false } else { atomic.AddInt32(&storeCount, 1) @@ -1195,30 +1388,53 @@ func (s *DHT) storeToAlphaNodes(ctx context.Context, nl *NodeList, data []byte, break } - logEntry := log.P2P().WithContext(ctx).WithField("node", nl.Nodes[i]).WithField("task_id", taskID) n := nl.Nodes[i] if s.ignorelist.Banned(n) { - logEntry.Info("ignore node as its continuous failed count is above threshold") + logtrace.Info(ctx, "Ignore node as its continuous failed count is above threshold", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "node": n.String(), + "task_id": taskID, + }) continue } request := &StoreDataRequest{Data: data, Type: typ} response, err := s.sendStoreData(ctx, n, request) if err != nil { - logEntry.WithError(err).Error("send store data failed") + logtrace.Error(ctx, "Send store data failed", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "node": n.String(), + "task_id": taskID, + logtrace.FieldError: err.Error(), + }) } else if response.Status.Result != ResultOk { - logEntry.WithError(errors.New(response.Status.ErrMsg)).Error("reply store data failed") + logtrace.Error(ctx, "Reply store data failed", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "node": n.String(), + "task_id": taskID, + logtrace.FieldError: response.Status.ErrMsg, + }) } else { finalStoreCount++ } } if finalStoreCount >= int32(Alpha) { - log.WithContext(ctx).WithField("task_id", taskID).WithField("len-total-nodes", nl.Len()).WithField("skey", hex.EncodeToString(skey)).Debug("store data to alpha nodes success") + logtrace.Debug(ctx, "Store data to alpha nodes success", logtrace.Fields{ + logtrace.FieldModule: "dht", + "task_id": taskID, + "len_total_nodes": nl.Len(), + "skey": hex.EncodeToString(skey), + }) return nil } - log.WithContext(ctx).WithField("task_id", taskID).WithField("store-count", finalStoreCount).WithField("skey", hex.EncodeToString(skey)).Info("store data to alpha nodes failed") + logtrace.Info(ctx, "Store data to alpha nodes failed", logtrace.Fields{ + logtrace.FieldModule: "dht", + "task_id": taskID, + "store_count": finalStoreCount, + "skey": hex.EncodeToString(skey), + }) return fmt.Errorf("store data to alpha nodes failed, only %d nodes stored", finalStoreCount) } @@ -1227,7 +1443,9 @@ func (s *DHT) storeToAlphaNodes(ctx context.Context, nl *NodeList, data []byte, func (s *DHT) removeNode(ctx context.Context, node *Node) { // ensure this is not itself address if bytes.Equal(node.ID, s.ht.self.ID) { - log.P2P().WithContext(ctx).Debug("trying to remove itself") + logtrace.Debug(ctx, "Trying to remove itself", logtrace.Fields{ + logtrace.FieldModule: "p2p", + }) return } node.SetHashedID() @@ -1235,9 +1453,17 @@ func (s *DHT) removeNode(ctx context.Context, node *Node) { index := s.ht.bucketIndex(s.ht.self.HashedID, node.HashedID) if removed := s.ht.RemoveNode(index, node.ID); !removed { - log.P2P().WithContext(ctx).Errorf("remove node %s not found in bucket %d", node.String(), index) + logtrace.Error(ctx, "Remove node not found in bucket", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "node": node.String(), + "bucket": index, + }) } else { - log.P2P().WithContext(ctx).Infof("removed node %s from bucket %d success", node.String(), index) + logtrace.Info(ctx, "Removed node from bucket success", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "node": node.String(), + "bucket": index, + }) } } @@ -1261,7 +1487,12 @@ func (s *DHT) IterateBatchStore(ctx context.Context, values [][]byte, typ int, i contacted := make(map[string]bool) hashes := make([][]byte, len(values)) - log.WithContext(ctx).WithField("task-id", id).WithField("keys", len(values)).WithField("len nodes", len(s.ht.nodes())).Info("iterate batch store begin") + logtrace.Info(ctx, "Iterate batch store begin", logtrace.Fields{ + logtrace.FieldModule: "dht", + "task_id": id, + "keys": len(values), + "len_nodes": len(s.ht.nodes()), + }) for i := 0; i < len(values); i++ { target, _ := utils.Blake3Hash(values[i]) hashes[i] = target @@ -1276,19 +1507,30 @@ func (s *DHT) IterateBatchStore(ctx context.Context, values [][]byte, typ int, i var i int for { i++ - log.WithContext(ctx).WithField("task-id", id).WithField("iter", i).WithField("keys", len(values)).Debug("iterate batch store begin") + logtrace.Debug(ctx, "Iterate batch store begin", logtrace.Fields{ + logtrace.FieldModule: "dht", + "task_id": id, + "iter": i, + "keys": len(values), + }) changed = false localClosestNodes := make(map[string]*NodeList) responses, atleastOneContacted := s.batchFindNode(ctx, hashes, knownNodes, contacted, id) if !atleastOneContacted { - log.WithContext(ctx).Info("Break") + logtrace.Info(ctx, "Break", logtrace.Fields{ + logtrace.FieldModule: "dht", + }) break } for response := range responses { if response.Error != nil { - log.WithContext(ctx).WithError(response.Error).WithField("task-id", id).Error("batch find node failed on a node") + logtrace.Error(ctx, "Batch find node failed on a node", logtrace.Fields{ + logtrace.FieldModule: "dht", + "task_id": id, + logtrace.FieldError: response.Error.Error(), + }) continue } @@ -1317,7 +1559,12 @@ func (s *DHT) IterateBatchStore(ctx context.Context, values [][]byte, typ int, i // we now need to check if the nodes in the globalClosestContacts Map are still in the top 6 // if yes, we can store the data to them // if not, we need to send calls to the newly found nodes to inquire about the top 6 nodes - log.WithContext(ctx).WithField("task-id", id).WithField("iter", i).WithField("keys", len(values)).Logger.Infof("check closest nodes & beign store") + logtrace.Info(ctx, "Check closest nodes & begin store", logtrace.Fields{ + logtrace.FieldModule: "dht", + "task_id": id, + "iter": i, + "keys": len(values), + }) for key, nodesList := range localClosestNodes { if nodesList == nil { continue @@ -1365,7 +1612,11 @@ func (s *DHT) IterateBatchStore(ctx context.Context, values [][]byte, typ int, i if response.Message != nil && response.Message.Sender != nil { sender = response.Message.Sender.String() } - log.WithContext(ctx).WithField("node", sender).WithError(response.Error).Error("batch store failed on a node") + logtrace.Error(ctx, "Batch store failed on a node", logtrace.Fields{ + logtrace.FieldModule: "dht", + "node": sender, + logtrace.FieldError: response.Error.Error(), + }) } if response.Message == nil { @@ -1376,22 +1627,35 @@ func (s *DHT) IterateBatchStore(ctx context.Context, values [][]byte, typ int, i if ok && v.Status.Result == ResultOk { successful++ } else { - errMsg := "unknwon error" + errMsg := "unknown error" if v != nil { errMsg = v.Status.ErrMsg } - log.WithContext(ctx).WithField("err", errMsg).WithField("task-id", id).Errorf("batch store to node %s failed", response.Message.Sender.String()) + logtrace.Error(ctx, "Batch store to node failed", logtrace.Fields{ + logtrace.FieldModule: "dht", + "err": errMsg, + "task_id": id, + "node": response.Message.Sender.String(), + }) } } if requests > 0 { successRate := float64(successful) / float64(requests) * 100 if successRate >= minimumDataStoreSuccessRate { - log.WithContext(ctx).WithField("task-id", id).Infof("Successful store operations: %.2f%%", successRate) + logtrace.Info(ctx, "Successful store operations", logtrace.Fields{ + logtrace.FieldModule: "dht", + "task_id": id, + "success_rate": fmt.Sprintf("%.2f%%", successRate), + }) return nil } else { - log.WithContext(ctx).WithField("task-id", id).Infof("Failed to achieve desired success rate, only: %.2f%%", successRate) + logtrace.Info(ctx, "Failed to achieve desired success rate", logtrace.Fields{ + logtrace.FieldModule: "dht", + "task_id": id, + "success_rate": fmt.Sprintf("%.2f%%", successRate), + }) return fmt.Errorf("failed to achieve desired success rate, only: %.2f%% successful", successRate) } } @@ -1406,9 +1670,15 @@ func (s *DHT) batchStoreNetwork(ctx context.Context, values [][]byte, nodes map[ var wg sync.WaitGroup for key, node := range nodes { - log.WithContext(ctx).WithField("Port#", node.String()).Info("node") + logtrace.Info(ctx, "Node", logtrace.Fields{ + logtrace.FieldModule: "dht", + "port": node.String(), + }) if s.ignorelist.Banned(node) { - log.WithContext(ctx).WithField("node", node.String()).Debug("Ignoring banned node in batch store network call") + logtrace.Debug(ctx, "Ignoring banned node in batch store network call", logtrace.Fields{ + logtrace.FieldModule: "dht", + "node": node.String(), + }) continue } @@ -1431,14 +1701,22 @@ func (s *DHT) batchStoreNetwork(ctx context.Context, values [][]byte, nodes map[ totalBytes += len(values[idx]) } - log.WithContext(ctx).WithField("keys", len(toStore)).WithField("size-before-compress", utils.BytesIntToMB(totalBytes)).Debug("batch store to node") + logtrace.Debug(ctx, "Batch store to node", logtrace.Fields{ + logtrace.FieldModule: "dht", + "keys": len(toStore), + "size_before_compress": utils.BytesIntToMB(totalBytes), + }) data := &BatchStoreDataRequest{Data: toStore, Type: typ} request := s.newMessage(BatchStoreData, receiver, data) response, err := s.network.Call(ctx, request, false) if err != nil { s.ignorelist.IncrementCount(receiver) - log.P2P().WithContext(ctx).WithError(err).Debugf("network call batch store request %s failed", request.String()) + logtrace.Debug(ctx, "Network call batch store request failed", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + "request": request.String(), + }) responses <- &MessageWithError{Error: err, Message: response} return } @@ -1455,7 +1733,11 @@ func (s *DHT) batchStoreNetwork(ctx context.Context, values [][]byte, nodes map[ } func (s *DHT) batchFindNode(ctx context.Context, payload [][]byte, nodes map[string]*Node, contacted map[string]bool, txid string) (chan *MessageWithError, bool) { - log.WithContext(ctx).WithField("task-id", txid).WithField("nodes-count", len(nodes)).Debug("batch find node begin") + logtrace.Debug(ctx, "Batch find node begin", logtrace.Fields{ + logtrace.FieldModule: "dht", + "task_id": txid, + "nodes_count": len(nodes), + }) responses := make(chan *MessageWithError, len(nodes)) atleastOneContacted := false @@ -1467,7 +1749,11 @@ func (s *DHT) batchFindNode(ctx context.Context, payload [][]byte, nodes map[str continue } if s.ignorelist.Banned(node) { - log.WithContext(ctx).WithField("node", node.String()).WithField("txid", txid).Info("Ignoring banned node in batch find call") + logtrace.Info(ctx, "Ignoring banned node in batch find call", logtrace.Fields{ + logtrace.FieldModule: "dht", + "node": node.String(), + "txid": txid, + }) continue } @@ -1490,7 +1776,12 @@ func (s *DHT) batchFindNode(ctx context.Context, payload [][]byte, nodes map[str response, err := s.network.Call(ctx, request, false) if err != nil { s.ignorelist.IncrementCount(receiver) - log.WithContext(ctx).WithError(err).WithField("node", receiver.String()).WithField("txid", txid).Warn("batch find node network call request failed") + logtrace.Warn(ctx, "Batch find node network call request failed", logtrace.Fields{ + logtrace.FieldModule: "dht", + "node": receiver.String(), + "txid": txid, + logtrace.FieldError: err.Error(), + }) responses <- &MessageWithError{Error: err, Message: response} return } @@ -1501,7 +1792,12 @@ func (s *DHT) batchFindNode(ctx context.Context, payload [][]byte, nodes map[str } wg.Wait() close(responses) - log.WithContext(ctx).WithField("nodes-count", len(nodes)).WithField("len-resp", len(responses)).WithField("txid", txid).Debug("batch find node done") + logtrace.Debug(ctx, "Batch find node done", logtrace.Fields{ + logtrace.FieldModule: "dht", + "nodes_count": len(nodes), + "len_resp": len(responses), + "txid": txid, + }) return responses, atleastOneContacted } diff --git a/p2p/kademlia/fetch_and_store.go b/p2p/kademlia/fetch_and_store.go index deb69483..5dcfd695 100644 --- a/p2p/kademlia/fetch_and_store.go +++ b/p2p/kademlia/fetch_and_store.go @@ -10,7 +10,7 @@ import ( json "github.com/json-iterator/go" "github.com/LumeraProtocol/supernode/p2p/kademlia/domain" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" "github.com/LumeraProtocol/supernode/pkg/utils" "github.com/cenkalti/backoff/v4" ) @@ -26,12 +26,12 @@ const ( // FetchAndStore fetches all keys from the queries TODO replicate list, fetches value from respective nodes and stores them in the queries store func (s *DHT) FetchAndStore(ctx context.Context) error { - log.WithContext(ctx).Info("Getting fetch and store keys") + logtrace.Info(ctx, "Getting fetch and store keys", logtrace.Fields{}) keys, err := s.store.GetAllToDoRepKeys(failedKeysClosestContactsLookupCount+maxBatchAttempts+1, totalMaxAttempts) if err != nil { return fmt.Errorf("get all keys error: %w", err) } - log.WithContext(ctx).WithField("count", len(keys)).Info("got keys from queries store") + logtrace.Info(ctx, "got keys from queries store", logtrace.Fields{"count": len(keys)}) if len(keys) == 0 { return nil @@ -51,7 +51,7 @@ func (s *DHT) FetchAndStore(ctx context.Context) error { sKey, err := hex.DecodeString(info.Key) if err != nil { - log.WithContext(cctx).WithField("key", info.Key).WithField("ip", info.IP).WithError(err).Error("hex decode key failed") + logtrace.Error(cctx, "hex decode key failed", logtrace.Fields{"key": info.Key, "ip": info.IP, logtrace.FieldError: err}) return } @@ -69,32 +69,32 @@ func (s *DHT) FetchAndStore(ctx context.Context) error { }, b) if err != nil { - log.WithContext(cctx).WithField("key", info.Key).WithField("ip", info.IP).WithError(err).Error("fetch & store key failed") + logtrace.Error(cctx, "fetch & store key failed", logtrace.Fields{"key": info.Key, "ip": info.IP, logtrace.FieldError: err}) value, err = s.iterateFindValue(cctx, IterateFindValue, sKey) if err != nil { - log.WithContext(cctx).WithField("key", info.Key).WithField("ip", info.IP).WithError(err).Error("iterate fetch for replication failed") + logtrace.Error(cctx, "iterate fetch for replication failed", logtrace.Fields{"key": info.Key, "ip": info.IP, logtrace.FieldError: err}) return } else if len(value) == 0 { - log.WithContext(cctx).WithField("key", info.Key).WithField("ip", info.IP).WithError(err).Error("iterate fetch for replication failed 0 val") + logtrace.Error(cctx, "iterate fetch for replication failed 0 val", logtrace.Fields{"key": info.Key, "ip": info.IP, logtrace.FieldError: err}) return } - log.WithContext(cctx).WithField("key", info.Key).WithField("ip", info.IP).Info("iterate fetch for replication success") + logtrace.Info(cctx, "iterate fetch for replication success", logtrace.Fields{"key": info.Key, "ip": info.IP}) } if err := s.store.Store(cctx, sKey, value, 0, false); err != nil { - log.WithContext(cctx).WithField("key", info.Key).WithField("ip", info.IP).WithError(err).Error("fetch & queries store key failed") + logtrace.Error(cctx, "fetch & queries store key failed", logtrace.Fields{"key": info.Key, "ip": info.IP, logtrace.FieldError: err}) return } if err := s.store.DeleteRepKey(info.Key); err != nil { - log.WithContext(cctx).WithField("key", info.Key).WithField("ip", info.IP).WithError(err).Error("delete key from todo list failed") + logtrace.Error(cctx, "delete key from todo list failed", logtrace.Fields{"key": info.Key, "ip": info.IP, logtrace.FieldError: err}) return } atomic.AddInt32(&successCounter, 1) // Increment the counter atomically - log.WithContext(cctx).WithField("key", info.Key).WithField("ip", info.IP).Info("fetch & store key success") + logtrace.Info(cctx, "fetch & store key success", logtrace.Fields{"key": info.Key, "ip": info.IP}) }(key) time.Sleep(100 * time.Millisecond) @@ -102,19 +102,19 @@ func (s *DHT) FetchAndStore(ctx context.Context) error { //wg.Wait() - log.WithContext(ctx).WithField("todo-keys", len(keys)).WithField("successfully-added-keys", atomic.LoadInt32(&successCounter)).Infof("Successfully fetched & stored keys") // Log the final count + logtrace.Info(ctx, "Successfully fetched & stored keys", logtrace.Fields{"todo-keys": len(keys), "successfully-added-keys": atomic.LoadInt32(&successCounter)}) // Log the final count return nil } // BatchFetchAndStoreFailedKeys fetches all failed keys from the queries TODO replicate list, fetches value from respective nodes and stores them in the queries store func (s *DHT) BatchFetchAndStoreFailedKeys(ctx context.Context) error { - log.WithContext(ctx).Debug("Getting failed batch fetch and store keys") + logtrace.Debug(ctx, "Getting failed batch fetch and store keys", logtrace.Fields{}) keys, err := s.store.GetAllToDoRepKeys(maxBatchAttempts+1, failedKeysClosestContactsLookupCount+maxBatchAttempts+1) // 2 - 14 if err != nil { return fmt.Errorf("get all keys error: %w", err) } - log.WithContext(ctx).WithField("count", len(keys)).Info("read failed keys from store") + logtrace.Info(ctx, "read failed keys from store", logtrace.Fields{"count": len(keys)}) if len(keys) == 0 { return nil @@ -125,7 +125,7 @@ func (s *DHT) BatchFetchAndStoreFailedKeys(ctx context.Context) error { igList := s.ignorelist.ToNodeList() sKey, err := hex.DecodeString(keys[i].Key) if err != nil { - log.WithContext(ctx).WithField("key", keys[i].Key).WithField("ip", keys[i].IP).WithError(err).Error("hex decode key failed") + logtrace.Error(ctx, "hex decode key failed", logtrace.Fields{"key": keys[i].Key, "ip": keys[i].IP, logtrace.FieldError: err}) continue } @@ -143,10 +143,10 @@ func (s *DHT) BatchFetchAndStoreFailedKeys(ctx context.Context) error { repKeys = append(repKeys, repKey) } } - log.WithField("count", len(repKeys)).Info("got 2nd tier replication keys from queries store") + logtrace.Info(ctx, "got 2nd tier replication keys from queries store", logtrace.Fields{"count": len(repKeys)}) if err := s.GroupAndBatchFetch(ctx, repKeys, 0, false); err != nil { - log.WithContext(ctx).WithError(err).Error("group and batch fetch failed-keys error") + logtrace.Error(ctx, "group and batch fetch failed-keys error", logtrace.Fields{logtrace.FieldError: err}) return fmt.Errorf("group and batch fetch failed keys error: %w", err) } @@ -155,19 +155,19 @@ func (s *DHT) BatchFetchAndStoreFailedKeys(ctx context.Context) error { // BatchFetchAndStore fetches all keys from the queries TODO replicate list, fetches value from respective nodes and stores them in the queries store func (s *DHT) BatchFetchAndStore(ctx context.Context) error { - log.WithContext(ctx).Debug("Getting batch fetch and store keys") + logtrace.Debug(ctx, "Getting batch fetch and store keys", logtrace.Fields{}) keys, err := s.store.GetAllToDoRepKeys(0, maxBatchAttempts) if err != nil { return fmt.Errorf("get all keys error: %w", err) } - log.WithContext(ctx).WithField("count", len(keys)).Info("got batch todo rep-keys from queries store") + logtrace.Info(ctx, "got batch todo rep-keys from queries store", logtrace.Fields{"count": len(keys)}) if len(keys) == 0 { return nil } if err := s.GroupAndBatchFetch(ctx, keys, 0, false); err != nil { - log.WithContext(ctx).WithError(err).Error("group and batch fetch error") + logtrace.Error(ctx, "group and batch fetch error", logtrace.Fields{logtrace.FieldError: err}) return fmt.Errorf("group and batch fetch error: %w", err) } @@ -213,13 +213,12 @@ func (s *DHT) GroupAndBatchFetch(ctx context.Context, repKeys []domain.ToRepKey, totalKeysFound := 0 for len(stringKeys) > 0 && iterations < maxSingleBatchIterations { iterations++ - log.WithContext(ctx).WithField("node-ip", node.IP).WithField("count", len(stringKeys)).WithField("keys[0]", stringKeys[0]). - WithField("keys[len()]", stringKeys[len(stringKeys)-1]).Info("fetching batch values from node") + logtrace.Info(ctx, "fetching batch values from node", logtrace.Fields{"node-ip": node.IP, "count": len(stringKeys), "keys[0]": stringKeys[0], "keys[len()]": stringKeys[len(stringKeys)-1]}) isDone, retMap, failedKeys, err := s.GetBatchValuesFromNode(ctx, stringKeys, node) if err != nil { // Log the error but don't stop the process, continue to the next node - log.WithContext(ctx).WithField("node-ip", node.IP).WithError(err).Info("failed to get batch values") + logtrace.Info(ctx, "failed to get batch values", logtrace.Fields{"node-ip": node.IP, logtrace.FieldError: err}) continue } @@ -239,7 +238,7 @@ func (s *DHT) GroupAndBatchFetch(ctx context.Context, repKeys []domain.ToRepKey, err = s.store.StoreBatch(ctx, response, datatype, isOriginal) if err != nil { // Log the error but don't stop the process, continue to the next node - log.WithContext(ctx).WithField("node-ip", node.IP).WithError(err).Info("failed to store batch values") + logtrace.Info(ctx, "failed to store batch values", logtrace.Fields{"node-ip": node.IP, logtrace.FieldError: err}) continue } @@ -247,16 +246,16 @@ func (s *DHT) GroupAndBatchFetch(ctx context.Context, repKeys []domain.ToRepKey, err = s.store.BatchDeleteRepKeys(stringDelKeys) if err != nil { // Log the error but don't stop the process, continue to the next node - log.WithContext(ctx).WithField("node-ip", node.IP).WithError(err).Info("failed to delete rep keys") + logtrace.Info(ctx, "failed to delete rep keys", logtrace.Fields{"node-ip": node.IP, logtrace.FieldError: err}) continue } } else { - log.WithContext(ctx).WithField("node-ip", node.IP).Warn("no values found in batch fetch") + logtrace.Warn(ctx, "no values found in batch fetch", logtrace.Fields{"node-ip": node.IP}) } if isDone && len(failedKeys) > 0 { if err := s.store.IncrementAttempts(failedKeys); err != nil { - log.WithContext(ctx).WithField("node-ip", node.IP).WithError(err).Info("failed to increment attempts") + logtrace.Info(ctx, "failed to increment attempts", logtrace.Fields{"node-ip": node.IP, logtrace.FieldError: err}) // not adding 'continue' here because we want to delete the keys from the todo list } } else if isDone { @@ -266,7 +265,7 @@ func (s *DHT) GroupAndBatchFetch(ctx context.Context, repKeys []domain.ToRepKey, } } - log.WithContext(ctx).WithField("node-ip", node.IP).WithField("count", totalKeysFound).WithField("iterations", iterations).Info("fetch batch values from node successfully") + logtrace.Info(ctx, "fetch batch values from node successfully", logtrace.Fields{"node-ip": node.IP, "count": totalKeysFound, "iterations": iterations}) } } @@ -275,7 +274,7 @@ func (s *DHT) GroupAndBatchFetch(ctx context.Context, repKeys []domain.ToRepKey, // GetBatchValuesFromNode get values from node in bateches func (s *DHT) GetBatchValuesFromNode(ctx context.Context, keys []string, n *Node) (bool, map[string][]byte, []string, error) { - log.WithContext(ctx).WithField("node-ip", n.IP).WithField("keys", len(keys)).Info("sending batch fetch request") + logtrace.Info(ctx, "sending batch fetch request", logtrace.Fields{"node-ip": n.IP, "keys": len(keys)}) messageType := BatchFindValues @@ -324,7 +323,7 @@ func (s *DHT) GetBatchValuesFromNode(ctx context.Context, keys []string, n *Node bo.Multiplier = 1 if err := backoff.Retry(operation, bo); err != nil { - log.P2P().WithContext(ctx).WithError(err).Debugf("network call request %s failed", request.String()) + logtrace.Debug(ctx, fmt.Sprintf("network call request %s failed", request.String()), logtrace.Fields{logtrace.FieldModule: "p2p", logtrace.FieldError: err}) return false, nil, nil, fmt.Errorf("network call request %s failed: %w", request.String(), err) } @@ -348,8 +347,7 @@ func (s *DHT) GetBatchValuesFromNode(ctx context.Context, keys []string, n *Node if err != nil { return isDone, nil, nil, fmt.Errorf("failed to verify and filter data: %w", err) } - log.WithContext(ctx).WithField("node-ip", n.IP).WithField("received-keys", len(decompressedMap)). - WithField("verified-keys", len(retMap)).WithField("failed-keys", len(failedKeys)).Info("batch fetch response rcvd and keys verified") + logtrace.Info(ctx, "batch fetch response rcvd and keys verified", logtrace.Fields{"node-ip": n.IP, "received-keys": len(decompressedMap), "verified-keys": len(retMap), "failed-keys": len(failedKeys)}) return v.Done, retMap, failedKeys, nil } @@ -372,7 +370,7 @@ func VerifyAndFilter(decompressedMap map[string][]byte) (map[string][]byte, []st hash, err := utils.Blake3Hash(value) if err != nil { failedKeys = append(failedKeys, key) - log.WithError(err).Error("failed to compute hash") + logtrace.Error(context.Background(), "failed to compute hash", logtrace.Fields{logtrace.FieldError: err}) continue } @@ -383,7 +381,7 @@ func VerifyAndFilter(decompressedMap map[string][]byte) (map[string][]byte, []st if hashHex == key { retMap[key] = value } else { - log.WithField("key", key).WithField("hash", hashHex).Error("hash mismatch") + logtrace.Error(context.Background(), "hash mismatch", logtrace.Fields{"key": key, "hash": hashHex}) failedKeys = append(failedKeys, key) } } diff --git a/p2p/kademlia/helpers/timer.go b/p2p/kademlia/helpers/timer.go index e45951b1..71735a71 100644 --- a/p2p/kademlia/helpers/timer.go +++ b/p2p/kademlia/helpers/timer.go @@ -4,7 +4,7 @@ import ( "context" "time" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" ) // StartTimer news a timer for doing the function @@ -23,7 +23,10 @@ func StartTimer(ctx context.Context, name string, done chan struct{}, interval t case <-ticker.C: // do the function if err := fn(); err != nil { - log.P2P().WithContext(ctx).WithError(err).Errorf("run worker(%s) failed", name) + logtrace.Error(ctx, "timer function failed", logtrace.Fields{ + logtrace.FieldModule: "helpers", + logtrace.FieldError: err.Error(), + }) } // reset the timer diff --git a/p2p/kademlia/network.go b/p2p/kademlia/network.go index a3c5bdbf..88100057 100644 --- a/p2p/kademlia/network.go +++ b/p2p/kademlia/network.go @@ -20,7 +20,7 @@ import ( "go.uber.org/ratelimit" "github.com/LumeraProtocol/supernode/pkg/errors" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" "golang.org/x/sync/semaphore" "google.golang.org/grpc/credentials" ) @@ -78,11 +78,17 @@ func NewNetwork(ctx context.Context, dht *DHT, self *Node, tc credentials.Transp // new tcp listener listener, err := net.Listen("tcp", addr) if err != nil { - log.P2P().Debugf("Error trying to get tcp socket: %s", err) + logtrace.Debug(ctx, "Error trying to get tcp socket", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + }) return nil, err } s.listener = listener - log.P2P().Debugf("Listening on: %s", addr) + logtrace.Debug(ctx, "Listening on", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "address": addr, + }) return s, nil } @@ -103,7 +109,10 @@ func (s *Network) Stop(ctx context.Context) { // close the socket if s.listener != nil { if err := s.listener.Close(); err != nil { - log.P2P().WithContext(ctx).WithError(err).Errorf("close socket failed") + logtrace.Error(ctx, "Close socket failed", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + }) } } } @@ -226,7 +235,7 @@ func (s *Network) handleStoreData(ctx context.Context, message *Message) (res [] return s.generateResponseMessage(StoreData, message.Sender, ResultFailed, err.Error()) } - log.P2P().WithContext(ctx).Debugf("handle store data: %v", message.String()) + logtrace.Debug(ctx, "Handle store data", logtrace.Fields{logtrace.FieldModule: "p2p", "message": message.String()}) // add the sender to queries hash table s.dht.addNode(ctx, message.Sender) @@ -267,7 +276,7 @@ func (s *Network) handleReplicate(ctx context.Context, message *Message) (res [] return s.generateResponseMessage(Replicate, message.Sender, ResultFailed, err.Error()) } - log.P2P().WithContext(ctx).Debugf("handle replicate data: %v", message.String()) + logtrace.Debug(ctx, "Handle replicate data", logtrace.Fields{logtrace.FieldModule: "p2p", "message": message.String()}) if err := s.handleReplicateRequest(ctx, request, message.Sender.ID, message.Sender.IP, message.Sender.Port); err != nil { return s.generateResponseMessage(Replicate, message.Sender, ResultFailed, err.Error()) @@ -287,18 +296,33 @@ func (s *Network) handleReplicate(ctx context.Context, message *Message) (res [] func (s *Network) handleReplicateRequest(ctx context.Context, req *ReplicateDataRequest, id []byte, ip string, port uint16) error { keysToStore, err := s.dht.store.RetrieveBatchNotExist(ctx, req.Keys, 5000) if err != nil { - log.WithContext(ctx).WithField("keys", len(req.Keys)).WithField("from-ip", ip).Errorf("unable to retrieve batch replication keys: %v", err) + logtrace.Error(ctx, "Unable to retrieve batch replication keys", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + "keys": len(req.Keys), + "from-ip": ip, + }) return fmt.Errorf("unable to retrieve batch replication keys: %w", err) } - log.WithContext(ctx).WithField("to-store-keys", len(keysToStore)).WithField("rcvd-keys", len(req.Keys)).WithField("from-ip", ip).Debug("store batch replication keys to be stored") + logtrace.Debug(ctx, "Store batch replication keys to be stored", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "to-store-keys": len(keysToStore), + "rcvd-keys": len(req.Keys), + "from-ip": ip, + }) if len(keysToStore) > 0 { if err := s.dht.store.StoreBatchRepKeys(keysToStore, string(id), ip, port); err != nil { return fmt.Errorf("unable to store batch replication keys: %w", err) } - log.WithContext(ctx).WithField("to-store-keys", len(keysToStore)).WithField("rcvd-keys", len(req.Keys)).WithField("from-ip", ip).Info("store batch replication keys stored") + logtrace.Info(ctx, "Store batch replication keys stored", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "to-store-keys": len(keysToStore), + "rcvd-keys": len(req.Keys), + "from-ip": ip, + }) } return nil @@ -314,13 +338,20 @@ func (s *Network) handlePing(_ context.Context, message *Message) ([]byte, error func (s *Network) handleConn(ctx context.Context, rawConn net.Conn) { var conn net.Conn var err error - ctx = log.ContextWithPrefix(ctx, fmt.Sprintf("conn:%s->%s", rawConn.LocalAddr(), rawConn.RemoteAddr())) + logtrace.Debug(ctx, "Handle connection", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "local-addr": rawConn.LocalAddr().String(), + "remote-addr": rawConn.RemoteAddr().String(), + }) // do secure handshaking if s.tc != nil { conn, err = NewSecureServerConn(ctx, s.tc, rawConn) if err != nil { rawConn.Close() - log.WithContext(ctx).WithError(err).Error("server secure handshake failed") + logtrace.Error(ctx, "Server secure handshake failed", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + }) return } } else { @@ -342,7 +373,10 @@ func (s *Network) handleConn(ctx context.Context, rawConn net.Conn) { if err == io.EOF { return } - log.WithContext(ctx).WithError(err).Error("read and decode failed") + logtrace.Error(ctx, "Read and decode failed", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + }) return } reqID := uuid.New().String() @@ -352,14 +386,21 @@ func (s *Network) handleConn(ctx context.Context, rawConn net.Conn) { case FindNode: encoded, err := s.handleFindNode(ctx, request) if err != nil { - log.P2P().WithContext(ctx).WithError(err).Error("handle find node request failed") + logtrace.Error(ctx, "Handle find node request failed", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + }) + return } response = encoded case BatchFindNode: encoded, err := s.handleBatchFindNode(ctx, request) if err != nil { - log.P2P().WithContext(ctx).WithError(err).Error("handle batch find node request failed") + logtrace.Error(ctx, "Handle batch find node request failed", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + }) return } response = encoded @@ -367,14 +408,20 @@ func (s *Network) handleConn(ctx context.Context, rawConn net.Conn) { // handle the request for finding value encoded, err := s.handleFindValue(ctx, request) if err != nil { - log.P2P().WithContext(ctx).WithError(err).Error("handle find value request failed") + logtrace.Error(ctx, "Handle find value request failed", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + }) return } response = encoded case Ping: encoded, err := s.handlePing(ctx, request) if err != nil { - log.P2P().WithContext(ctx).WithError(err).Error("handle ping request failed") + logtrace.Error(ctx, "Handle ping request failed", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + }) return } response = encoded @@ -382,7 +429,10 @@ func (s *Network) handleConn(ctx context.Context, rawConn net.Conn) { // handle the request for storing data encoded, err := s.handleStoreData(ctx, request) if err != nil { - log.P2P().WithContext(ctx).WithError(err).Error("handle store data request failed") + logtrace.Error(ctx, "Handle store data request failed", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + }) return } response = encoded @@ -390,7 +440,10 @@ func (s *Network) handleConn(ctx context.Context, rawConn net.Conn) { // handle the request for replicate request encoded, err := s.handleReplicate(ctx, request) if err != nil { - log.P2P().WithContext(ctx).WithError(err).Error("handle replicate request failed") + logtrace.Error(ctx, "Handle replicate request failed", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + }) return } response = encoded @@ -398,7 +451,11 @@ func (s *Network) handleConn(ctx context.Context, rawConn net.Conn) { // handle the request for finding value encoded, err := s.handleBatchFindValues(ctx, request, reqID) if err != nil { - log.P2P().WithContext(ctx).WithField("p2p-req-id", reqID).WithError(err).Error("handle batch find values request failed") + logtrace.Error(ctx, "Handle batch find values request failed", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + "p2p-req-id": reqID, + }) return } response = encoded @@ -406,7 +463,10 @@ func (s *Network) handleConn(ctx context.Context, rawConn net.Conn) { // handle the request for storing data encoded, err := s.handleBatchStoreData(ctx, request) if err != nil { - log.WithContext(ctx).WithError(err).Error("handle batch store data request failed") + logtrace.Error(ctx, "Handle batch store data request failed", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + }) return } response = encoded @@ -414,18 +474,30 @@ func (s *Network) handleConn(ctx context.Context, rawConn net.Conn) { // handle the request for finding value encoded, err := s.handleGetValuesRequest(ctx, request, reqID) if err != nil { - log.WithContext(ctx).WithField("p2p-req-id", reqID).WithError(err).Error("handle batch get values request failed") + logtrace.Error(ctx, "Handle batch get values request failed", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + "p2p-req-id": reqID, + }) return } response = encoded default: - log.P2P().WithContext(ctx).Errorf("invalid message type: %v", request.MessageType) + logtrace.Error(ctx, "Invalid message type", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "message-type": request.MessageType, + }) return } // write the response if _, err := conn.Write(response); err != nil { - log.P2P().WithField("p2p-req-id", reqID).WithContext(ctx).WithError(err).Errorf("write failed %d", request.MessageType) + logtrace.Error(ctx, "Write failed", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + "p2p-req-id": reqID, + "message-type": request.MessageType, + }) return } } @@ -481,13 +553,20 @@ func (s *Network) serve(ctx context.Context) { if max := 1 * time.Second; tempDelay > max { tempDelay = max } - log.WithContext(ctx).WithError(err).Errorf("socket accept failed, retrying in %v", tempDelay) + logtrace.Error(ctx, "Socket accept failed, retrying", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + "retry-in": tempDelay.String(), + }) time.Sleep(tempDelay) continue } - log.WithContext(ctx).WithError(err).Error("socket accept failed") + logtrace.Error(ctx, "Socket accept failed", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + }) return } @@ -514,11 +593,15 @@ func (s *Network) Call(ctx context.Context, request *Message, isLong bool) (*Mes defer cancel() if request.Receiver != nil && request.Receiver.Port == 50052 { - log.P2P().WithContext(ctx).Error("invalid receiver port") + logtrace.Error(ctx, "Invalid receiver port", logtrace.Fields{ + logtrace.FieldModule: "p2p", + }) return nil, errors.New("invalid receiver port") } if request.Sender != nil && request.Sender.Port == 50052 { - log.P2P().WithContext(ctx).Error("invalid sender port") + logtrace.Error(ctx, "Invalid sender port", logtrace.Fields{ + logtrace.FieldModule: "p2p", + }) return nil, errors.New("invalid sender port") } @@ -571,18 +654,18 @@ func (s *Network) Call(ctx context.Context, request *Message, isLong bool) (*Mes func (s *Network) handleBatchFindValues(ctx context.Context, message *Message, reqID string) (res []byte, err error) { // Try to acquire the semaphore, wait up to 1 minute - log.WithContext(ctx).Debug("Attempting to acquire semaphore immediately.") + logtrace.Debug(ctx, "Attempting to acquire semaphore immediately", logtrace.Fields{logtrace.FieldModule: "p2p"}) if !s.sem.TryAcquire(1) { - log.WithContext(ctx).Info("Immediate acquisition failed. Waiting up to 1 minute.") + logtrace.Info(ctx, "Immediate acquisition failed. Waiting up to 1 minute", logtrace.Fields{logtrace.FieldModule: "p2p"}) ctxWithTimeout, cancel := context.WithTimeout(ctx, 1*time.Minute) defer cancel() if err := s.sem.Acquire(ctxWithTimeout, 1); err != nil { - log.WithContext(ctx).Error("Failed to acquire semaphore within 1 minute.") + logtrace.Error(ctx, "Failed to acquire semaphore within 1 minute", logtrace.Fields{logtrace.FieldModule: "p2p"}) // failed to acquire semaphore within 1 minute return s.generateResponseMessage(BatchFindValues, message.Sender, ResultFailed, errorBusy) } - log.WithContext(ctx).Info("Semaphore acquired after waiting.") + logtrace.Info(ctx, "Semaphore acquired after waiting", logtrace.Fields{logtrace.FieldModule: "p2p"}) } // Add a defer function to recover from panic @@ -591,7 +674,10 @@ func (s *Network) handleBatchFindValues(ctx context.Context, message *Message, r if r := recover(); r != nil { // Log the error or handle it as you see fit - log.WithContext(ctx).Errorf("HandleBatchFindValues Recovered from panic: %v", r) + logtrace.Error(ctx, "HandleBatchFindValues recovered from panic", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "panic": fmt.Sprintf("%v", r), + }) // Convert panic to error switch t := r.(type) { @@ -642,7 +728,10 @@ func (s *Network) handleGetValuesRequest(ctx context.Context, message *Message, return s.generateResponseMessage(BatchGetValues, message.Sender, ResultFailed, err.Error()) } - log.WithContext(ctx).Infof("batch get values request received from %s", message.Sender.String()) + logtrace.Info(ctx, "Batch get values request received", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "from": message.Sender.String(), + }) // add the sender to queries hash table s.dht.addNode(ctx, message.Sender) @@ -659,7 +748,12 @@ func (s *Network) handleGetValuesRequest(ctx context.Context, message *Message, return s.generateResponseMessage(BatchGetValues, message.Sender, ResultFailed, err.Error()) } - log.WithContext(ctx).WithField("requested-keys", len(keys)).WithField("found", count).WithField("sender", message.Sender.String()).Info("batch get values request processed") + logtrace.Info(ctx, "Batch get values request processed", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "requested-keys": len(keys), + "found": count, + "sender": message.Sender.String(), + }) for i, key := range keys { val := KeyValWithClosest{ @@ -692,25 +786,52 @@ func (s *Network) handleGetValuesRequest(ctx context.Context, message *Message, } func (s *Network) handleBatchFindValuesRequest(ctx context.Context, req *BatchFindValuesRequest, ip string, reqID string) (isDone bool, compressedData []byte, err error) { - log.WithContext(ctx).WithField("p2p-req-id", reqID).WithField("keys", len(req.Keys)).WithField("from-ip", ip).Info("batch find values request received") + // log.WithContext(ctx).WithField("p2p-req-id", reqID).WithField("keys", len(req.Keys)).WithField("from-ip", ip).Info("batch find values request received") + logtrace.Info(ctx, "Batch find values request received", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "from": ip, + "keys": len(req.Keys), + "p2p-req-id": reqID, + }) if len(req.Keys) > 0 { - log.WithContext(ctx).WithField("p2p-req-id", reqID).WithField("keys[0]", req.Keys[0]).WithField("keys[len]", req.Keys[len(req.Keys)-1]). - WithField("from-ip", ip).Debug("first & last batch keys") + // log.WithContext(ctx).WithField("p2p-req-id", reqID).WithField("keys[0]", req.Keys[0]).WithField("keys[len]", req.Keys[len(req.Keys)-1]). + // WithField("from-ip", ip).Debug("first & last batch keys") + logtrace.Debug(ctx, "First & last batch keys", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "p2p-req-id": reqID, + "keys[0]": req.Keys[0], + "keys[len]": req.Keys[len(req.Keys)-1], + "from-ip": ip, + }) } values, count, err := s.dht.store.RetrieveBatchValues(ctx, req.Keys, true) if err != nil { return false, nil, fmt.Errorf("failed to retrieve batch values: %w", err) } - log.WithContext(ctx).WithField("p2p-req-id", reqID).WithField("values-len", len(values)).WithField("found", count).WithField("from-ip", ip).Info("batch find values request processed") + // log.WithContext(ctx).WithField("p2p-req-id", reqID).WithField("values-len", len(values)).WithField("found", count).WithField("from-ip", ip).Info("batch find values request processed") + logtrace.Info(ctx, "Batch find values request processed", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "p2p-req-id": reqID, + "values-len": len(values), + "found": count, + "from-ip": ip, + }) isDone, count, compressedData, err = findOptimalCompression(count, req.Keys, values) if err != nil { return false, nil, fmt.Errorf("failed to find optimal compression: %w", err) } - log.WithContext(ctx).WithField("p2p-req-id", reqID).WithField("compressed-data-len", utils.BytesToMB(uint64(len(compressedData)))).WithField("found", count). - WithField("from-ip", ip).Info("batch find values response sent") + // log.WithContext(ctx).WithField("p2p-req-id", reqID).WithField("compressed-data-len", utils.BytesToMB(uint64(len(compressedData)))).WithField("found", count). + // WithField("from-ip", ip).Info("batch find values response sent") + logtrace.Info(ctx, "Batch find values response sent", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "p2p-req-id": reqID, + "compressed-data-len": utils.BytesToMB(uint64(len(compressedData))), + "found": count, + "from-ip": ip, + }) return isDone, compressedData, nil } @@ -728,7 +849,11 @@ func findOptimalCompression(count int, keys []string, values [][]byte) (bool, in // If the initial compressed data is under the threshold if utils.BytesIntToMB(len(compressedData)) < defaultMaxPayloadSize { - log.WithField("compressed-data-len", utils.BytesToMB(uint64(len(compressedData)))).WithField("count", count).Debug("initial compression") + // log.WithField("compressed-data-len", utils.BytesToMB(uint64(len(compressedData)))).WithField("count", count).Debug("initial compression") + logtrace.Debug(context.TODO(), "Initial compression", logtrace.Fields{ + "compressed-data-len": utils.BytesToMB(uint64(len(compressedData))), + "count": count, + }) return true, len(dataMap), compressedData, nil } @@ -736,7 +861,12 @@ func findOptimalCompression(count int, keys []string, values [][]byte) (bool, in currentValuesCount := count for utils.BytesIntToMB(len(compressedData)) >= defaultMaxPayloadSize { size := utils.BytesIntToMB(len(compressedData)) - log.WithField("compressed-data-len", size).WithField("current-count", currentValuesCount).WithField("iter", iter).Debug("optimal compression") + // log.WithField("compressed-data-len", size).WithField("current-count", currentValuesCount).WithField("iter", iter).Debug("optimal compression") + logtrace.Debug(context.TODO(), "Optimal compression", logtrace.Fields{ + "compressed-data-len": size, + "current-count": currentValuesCount, + "iter": iter, + }) iter++ // Find top 10 heaviest values and set their keys to nil in the map var heavyKeys []string @@ -806,7 +936,11 @@ func findTopHeaviestKeys(dataMap map[string][]byte, size int) (int, []string) { } if size > (2 * defaultMaxPayloadSize) { - log.Debug("find optimal compression decreasing payload by half") + // log.Debug("find optimal compression decreasing payload by half") + logtrace.Debug(context.TODO(), "Find optimal compression decreasing payload by half", logtrace.Fields{ + "size": size, + "count": count, + }) n = count / 2 } @@ -831,7 +965,12 @@ func (s *Network) handleBatchStoreData(ctx context.Context, message *Message) (r return s.generateResponseMessage(BatchStoreData, message.Sender, ResultFailed, err.Error()) } - log.P2P().WithContext(ctx).Info("handle batch store data request received") + // log.P2P().WithContext(ctx).Info("handle batch store data request received") + logtrace.Info(ctx, "Handle batch store data request received", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "sender": message.Sender.String(), + "keys": len(request.Data), + }) // add the sender to queries hash table s.dht.addNode(ctx, message.Sender) @@ -846,7 +985,12 @@ func (s *Network) handleBatchStoreData(ctx context.Context, message *Message) (r Result: ResultOk, }, } - log.P2P().WithContext(ctx).Info("handle batch store data request processed") + // log.P2P().WithContext(ctx).Info("handle batch store data request processed") + logtrace.Info(ctx, "Handle batch store data request processed", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "sender": message.Sender.String(), + "keys": len(request.Data), + }) // new a response message resMsg := s.dht.newMessage(BatchStoreData, message.Sender, response) @@ -876,13 +1020,22 @@ func (s *Network) handleBatchFindNode(ctx context.Context, message *Message) (re } closestMap := make(map[string][]*Node) - log.WithContext(ctx).WithField("sender", message.Sender.String()).Info("Batch Find Nodes Request Received") + // log.WithContext(ctx).WithField("sender", message.Sender.String()).Info("Batch Find Nodes Request Received") + logtrace.Info(ctx, "Batch Find Nodes Request Received", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "sender": message.Sender.String(), + "hashed-targets": len(request.HashedTarget), + }) for _, hashedTargetID := range request.HashedTarget { closest, _ := s.dht.ht.closestContacts(K, hashedTargetID, []*Node{message.Sender}) closestMap[base58.Encode(hashedTargetID)] = closest.Nodes } response.ClosestNodes = closestMap - log.WithContext(ctx).WithField("sender", message.Sender.String()).Info("Batch Find Nodes Request Processed") + // log.WithContext(ctx).WithField("sender", message.Sender.String()).Info("Batch Find Nodes Request Processed") + logtrace.Info(ctx, "Batch Find Nodes Request Processed", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "sender": message.Sender.String(), + }) // new a response message resMsg := s.dht.newMessage(BatchFindNode, message.Sender, response) @@ -918,7 +1071,12 @@ func (s *Network) generateResponseMessage(messageType int, receiver *Node, resul func (s *Network) handlePanic(ctx context.Context, sender *Node, messageType int) (res []byte, err error) { if r := recover(); r != nil { - log.WithContext(ctx).Errorf("p2p network: recovered from panic: %v", r) + // log.WithContext(ctx).Errorf("p2p network: recovered from panic: %v", r) + logtrace.Error(ctx, "P2P network: recovered from panic", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "sender": sender.String(), + "message-type": messageType, + }) switch t := r.(type) { case string: @@ -930,7 +1088,11 @@ func (s *Network) handlePanic(ctx context.Context, sender *Node, messageType int } if res, err := s.generateResponseMessage(messageType, sender, ResultFailed, err.Error()); err != nil { - log.WithContext(ctx).Errorf("Error generating response message: %v", err) + // log.WithContext(ctx).Errorf("Error generating response message: %v", err) + logtrace.Error(ctx, "Error generating response message", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + }) } else { return res, err } diff --git a/p2p/kademlia/node.go b/p2p/kademlia/node.go index 1214773e..d9208136 100644 --- a/p2p/kademlia/node.go +++ b/p2p/kademlia/node.go @@ -2,13 +2,14 @@ package kademlia import ( "bytes" + "context" "fmt" "math/big" "sort" "strings" "sync" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" "github.com/LumeraProtocol/supernode/pkg/utils" ) @@ -163,7 +164,7 @@ func (s *NodeList) distance(id1, id2 []byte) *big.Int { // Sort sorts nodes func (s *NodeList) Sort() { if len(s.Comparator) == 0 { - log.Warn("sort without comparator!!") + logtrace.Warn(context.Background(), "sort without comparator", logtrace.Fields{logtrace.FieldModule: "p2p"}) } s.Mux.Lock() diff --git a/p2p/kademlia/node_activity.go b/p2p/kademlia/node_activity.go index d2c296c9..b4700667 100644 --- a/p2p/kademlia/node_activity.go +++ b/p2p/kademlia/node_activity.go @@ -4,7 +4,7 @@ import ( "context" "time" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" "github.com/LumeraProtocol/supernode/pkg/utils" ) @@ -16,11 +16,14 @@ func (s *DHT) checkNodeActivity(ctx context.Context) { return case <-time.After(checkNodeActivityInterval): // Adjust the interval as needed if !utils.CheckInternetConnectivity() { - log.WithContext(ctx).Info("no internet connectivity, not checking node activity") + logtrace.Info(ctx, "no internet connectivity, not checking node activity", logtrace.Fields{}) } else { repInfo, err := s.store.GetAllReplicationInfo(ctx) if err != nil { - log.P2P().WithContext(ctx).WithError(err).Errorf("get all replicationInfo failed") + logtrace.Error(ctx, "get all replicationInfo failed", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + }) } for _, info := range repInfo { @@ -36,11 +39,19 @@ func (s *DHT) checkNodeActivity(ctx context.Context) { // invoke the request and handle the response _, err := s.network.Call(ctx, request, false) if err != nil { - log.P2P().WithContext(ctx).WithError(err).WithField("ip", info.IP).WithField("node_id", string(info.ID)). - Debug("failed to ping node") + logtrace.Debug(ctx, "failed to ping node", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + "ip": info.IP, + "node_id": string(info.ID), + }) if info.Active { - log.P2P().WithContext(ctx).WithError(err).WithField("ip", info.IP).WithField("node_id", string(info.ID)). - Error("setting node to inactive") + logtrace.Error(ctx, "setting node to inactive", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + "ip": info.IP, + "node_id": string(info.ID), + }) // add node to ignore list // we maintain this list to avoid pinging nodes that are not responding @@ -50,7 +61,12 @@ func (s *DHT) checkNodeActivity(ctx context.Context) { // mark node as inactive in database if err := s.store.UpdateIsActive(ctx, string(info.ID), false, false); err != nil { - log.P2P().WithContext(ctx).WithError(err).WithField("ip", info.IP).WithField("node_id", string(info.ID)).Error("failed to update replication info, node is inactive") + logtrace.Error(ctx, "failed to update replication info, node is inactive", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + "ip": info.IP, + "node_id": string(info.ID), + }) } } @@ -59,16 +75,29 @@ func (s *DHT) checkNodeActivity(ctx context.Context) { s.ignorelist.Delete(node) if !info.Active { - log.P2P().WithContext(ctx).WithField("ip", info.IP).WithField("node_id", string(info.ID)).Info("node found to be active again") + logtrace.Info(ctx, "node found to be active again", logtrace.Fields{ + logtrace.FieldModule: "p2p", + "ip": info.IP, + "node_id": string(info.ID), + }) // add node adds in the route table s.addNode(ctx, node) if err := s.store.UpdateIsActive(ctx, string(info.ID), true, false); err != nil { - log.P2P().WithContext(ctx).WithError(err).WithField("ip", info.IP).WithField("node_id", string(info.ID)).Error("failed to update replication info, node is inactive") + logtrace.Error(ctx, "failed to update replication info, node is inactive", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + "ip": info.IP, + "node_id": string(info.ID), + }) } } if err := s.store.UpdateLastSeen(ctx, string(info.ID)); err != nil { - log.WithContext(ctx).WithError(err).WithField("ip", info.IP).WithField("node_id", string(info.ID)).Error("failed to update last seen") + logtrace.Error(ctx, "failed to update last seen", logtrace.Fields{ + logtrace.FieldError: err.Error(), + "ip": info.IP, + "node_id": string(info.ID), + }) } } } diff --git a/p2p/kademlia/redundant_data.go b/p2p/kademlia/redundant_data.go index 79b06f21..25adc099 100644 --- a/p2p/kademlia/redundant_data.go +++ b/p2p/kademlia/redundant_data.go @@ -6,21 +6,21 @@ import ( "encoding/hex" "time" + "github.com/LumeraProtocol/supernode/p2p/kademlia/domain" "github.com/LumeraProtocol/supernode/pkg/errors" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" "github.com/LumeraProtocol/supernode/pkg/utils" - "github.com/LumeraProtocol/supernode/p2p/kademlia/domain" ) func (s *DHT) startDisabledKeysCleanupWorker(ctx context.Context) error { - log.P2P().WithContext(ctx).Info("disabled keys cleanup worker started") + logtrace.Info(ctx, "disabled keys cleanup worker started", logtrace.Fields{logtrace.FieldModule: "p2p"}) for { select { case <-time.After(defaultCleanupInterval): s.cleanupDisabledKeys(ctx) case <-ctx.Done(): - log.P2P().WithContext(ctx).Error("closing disabled keys cleanup worker") + logtrace.Error(ctx, "closing disabled keys cleanup worker", logtrace.Fields{logtrace.FieldModule: "p2p"}) return nil } } @@ -40,7 +40,7 @@ func (s *DHT) cleanupDisabledKeys(ctx context.Context) error { for i := 0; i < len(disabledKeys); i++ { dec, err := hex.DecodeString(disabledKeys[i].Key) if err != nil { - log.P2P().WithContext(ctx).WithError(err).Error("decode disabled key failed") + logtrace.Error(ctx, "decode disabled key failed", logtrace.Fields{logtrace.FieldModule: "p2p", logtrace.FieldError: err.Error()}) continue } s.metaStore.Delete(ctx, dec) @@ -50,14 +50,14 @@ func (s *DHT) cleanupDisabledKeys(ctx context.Context) error { } func (s *DHT) startCleanupRedundantDataWorker(ctx context.Context) { - log.P2P().WithContext(ctx).Info("redundant data cleanup worker started") + logtrace.Info(ctx, "redundant data cleanup worker started", logtrace.Fields{logtrace.FieldModule: "p2p"}) for { select { case <-time.After(defaultRedundantDataCleanupInterval): s.cleanupRedundantDataWorker(ctx) case <-ctx.Done(): - log.P2P().WithContext(ctx).Error("closing disabled keys cleanup worker") + logtrace.Error(ctx, "closing disabled keys cleanup worker", logtrace.Fields{logtrace.FieldModule: "p2p"}) return } } @@ -66,7 +66,7 @@ func (s *DHT) startCleanupRedundantDataWorker(ctx context.Context) { func (s *DHT) cleanupRedundantDataWorker(ctx context.Context) { from := time.Now().AddDate(-5, 0, 0) // 5 years ago - log.P2P().WithContext(ctx).WithField("from", from).Info("getting all possible replication keys past five years") + logtrace.Info(ctx, "getting all possible replication keys past five years", logtrace.Fields{logtrace.FieldModule: "p2p", "from": from}) to := time.Now().UTC() replicationKeys := s.store.GetKeysForReplication(ctx, from, to) @@ -86,7 +86,7 @@ func (s *DHT) cleanupRedundantDataWorker(ctx context.Context) { removeKeys := make([]domain.DelKey, 0) for key, closestContacts := range closestContactsMap { if len(closestContacts) < Alpha { - log.P2P().WithContext(ctx).WithField("key", key).WithField("closest contacts", closestContacts).Info("not enough contacts to replicate") + logtrace.Info(ctx, "not enough contacts to replicate", logtrace.Fields{logtrace.FieldModule: "p2p", "key": key, "closest contacts": closestContacts}) continue } @@ -112,18 +112,18 @@ func (s *DHT) cleanupRedundantDataWorker(ctx context.Context) { if len(insertKeys) > 0 { if err := s.metaStore.BatchInsertDelKeys(ctx, insertKeys); err != nil { - log.P2P().WithContext(ctx).WithError(err).Error("insert keys failed") + logtrace.Error(ctx, "insert keys failed", logtrace.Fields{logtrace.FieldModule: "p2p", logtrace.FieldError: err.Error()}) return } - log.P2P().WithContext(ctx).WithField("count-del-keys", len(insertKeys)).Info("insert del keys success") + logtrace.Info(ctx, "insert del keys success", logtrace.Fields{logtrace.FieldModule: "p2p", "count-del-keys": len(insertKeys)}) } else { - log.P2P().WithContext(ctx).Info("No redundant key found to be stored in the storage") + logtrace.Info(ctx, "No redundant key found to be stored in the storage", logtrace.Fields{logtrace.FieldModule: "p2p"}) } if len(removeKeys) > 0 { if err := s.metaStore.BatchDeleteDelKeys(ctx, removeKeys); err != nil { - log.WithContext(ctx).WithError(err).Error("batch delete del-keys failed") + logtrace.Error(ctx, "batch delete del-keys failed", logtrace.Fields{logtrace.FieldError: err.Error()}) return } } @@ -131,14 +131,14 @@ func (s *DHT) cleanupRedundantDataWorker(ctx context.Context) { } func (s *DHT) startDeleteDataWorker(ctx context.Context) { - log.P2P().WithContext(ctx).Info("start delete data worker") + logtrace.Info(ctx, "start delete data worker", logtrace.Fields{logtrace.FieldModule: "p2p"}) for { select { case <-time.After(defaultDeleteDataInterval): s.deleteRedundantData(ctx) case <-ctx.Done(): - log.P2P().WithContext(ctx).Error("closing delete data worker") + logtrace.Error(ctx, "closing delete data worker", logtrace.Fields{logtrace.FieldModule: "p2p"}) return } } @@ -149,7 +149,7 @@ func (s *DHT) deleteRedundantData(ctx context.Context) { delKeys, err := s.metaStore.GetAllToDelKeys(delKeysCountThreshold) if err != nil { - log.P2P().WithContext(ctx).WithError(err).Error("get all to delete keys failed") + logtrace.Error(ctx, "get all to delete keys failed", logtrace.Fields{logtrace.FieldModule: "p2p", logtrace.FieldError: err.Error()}) return } @@ -157,7 +157,7 @@ func (s *DHT) deleteRedundantData(ctx context.Context) { // Check the available disk space isLow, err := utils.CheckDiskSpace(lowSpaceThreshold) if err != nil { - log.P2P().WithContext(ctx).WithError(err).Error("check disk space failed") + logtrace.Error(ctx, "check disk space failed", logtrace.Fields{logtrace.FieldModule: "p2p", logtrace.FieldError: err.Error()}) break } @@ -180,7 +180,7 @@ func (s *DHT) deleteRedundantData(ctx context.Context) { // Perform the deletion if err := s.store.BatchDeleteRecords(keysToDelete); err != nil { - log.P2P().WithContext(ctx).WithError(err).Error("batch delete records failed") + logtrace.Error(ctx, "batch delete records failed", logtrace.Fields{logtrace.FieldModule: "p2p", logtrace.FieldError: err.Error()}) break } diff --git a/p2p/kademlia/replication.go b/p2p/kademlia/replication.go index 885aaf24..b0c62652 100644 --- a/p2p/kademlia/replication.go +++ b/p2p/kademlia/replication.go @@ -8,9 +8,9 @@ import ( "encoding/hex" - "github.com/LumeraProtocol/supernode/pkg/errors" - "github.com/LumeraProtocol/supernode/pkg/log" "github.com/LumeraProtocol/supernode/p2p/kademlia/domain" + "github.com/LumeraProtocol/supernode/pkg/errors" + "github.com/LumeraProtocol/supernode/pkg/logtrace" "github.com/cenkalti/backoff/v4" ) @@ -34,7 +34,7 @@ var ( // StartReplicationWorker starts replication func (s *DHT) StartReplicationWorker(ctx context.Context) error { - log.P2P().WithContext(ctx).Info("replication worker started") + logtrace.Info(ctx, "replication worker started", logtrace.Fields{logtrace.FieldModule: "p2p"}) go s.checkNodeActivity(ctx) go s.StartBatchFetchAndStoreWorker(ctx) @@ -46,7 +46,7 @@ func (s *DHT) StartReplicationWorker(ctx context.Context) error { //log.WithContext(ctx).Info("replication worker disabled") s.Replicate(ctx) case <-ctx.Done(): - log.P2P().WithContext(ctx).Error("closing replication worker") + logtrace.Error(ctx, "closing replication worker", logtrace.Fields{logtrace.FieldModule: "p2p"}) return nil } } @@ -54,14 +54,14 @@ func (s *DHT) StartReplicationWorker(ctx context.Context) error { // StartBatchFetchAndStoreWorker starts replication func (s *DHT) StartBatchFetchAndStoreWorker(ctx context.Context) error { - log.P2P().WithContext(ctx).Info("batch fetch and store worker started") + logtrace.Info(ctx, "batch fetch and store worker started", logtrace.Fields{logtrace.FieldModule: "p2p"}) for { select { case <-time.After(defaultBatchFetchAndStoreInterval): s.BatchFetchAndStore(ctx) case <-ctx.Done(): - log.P2P().WithContext(ctx).Error("closing batch fetch & store worker") + logtrace.Error(ctx, "closing batch fetch & store worker", logtrace.Fields{logtrace.FieldModule: "p2p"}) return nil } } @@ -69,14 +69,14 @@ func (s *DHT) StartBatchFetchAndStoreWorker(ctx context.Context) error { // StartFailedFetchAndStoreWorker starts replication func (s *DHT) StartFailedFetchAndStoreWorker(ctx context.Context) error { - log.P2P().WithContext(ctx).Info("fetch and store worker started") + logtrace.Info(ctx, "fetch and store worker started", logtrace.Fields{logtrace.FieldModule: "p2p"}) for { select { case <-time.After(defaultFetchAndStoreInterval): s.BatchFetchAndStoreFailedKeys(ctx) case <-ctx.Done(): - log.P2P().WithContext(ctx).Error("closing fetch & store worker") + logtrace.Error(ctx, "closing fetch & store worker", logtrace.Fields{logtrace.FieldModule: "p2p"}) return nil } } @@ -101,12 +101,12 @@ func (s *DHT) updateReplicationNode(ctx context.Context, nodeID []byte, ip strin if ok { if err := s.store.UpdateReplicationInfo(ctx, info); err != nil { - log.P2P().WithContext(ctx).WithError(err).WithField("node_id", string(nodeID)).WithField("ip", ip).Error("failed to update replication info") + logtrace.Error(ctx, "failed to update replication info", logtrace.Fields{logtrace.FieldModule: "p2p", logtrace.FieldError: err.Error(), "node_id": string(nodeID), "ip": ip}) return err } } else { if err := s.store.AddReplicationInfo(ctx, info); err != nil { - log.P2P().WithContext(ctx).WithError(err).WithField("node_id", string(nodeID)).WithField("ip", ip).Error("failed to add replication info") + logtrace.Error(ctx, "failed to add replication info", logtrace.Fields{logtrace.FieldModule: "p2p", logtrace.FieldError: err.Error(), "node_id": string(nodeID), "ip": ip}) return err } } @@ -116,7 +116,7 @@ func (s *DHT) updateReplicationNode(ctx context.Context, nodeID []byte, ip strin func (s *DHT) updateLastReplicated(ctx context.Context, nodeID []byte, timestamp time.Time) error { if err := s.store.UpdateLastReplicated(ctx, string(nodeID), timestamp); err != nil { - log.P2P().WithContext(ctx).WithError(err).WithField("node_id", string(nodeID)).Error("failed to update replication info last replicated") + logtrace.Error(ctx, "failed to update replication info last replicated", logtrace.Fields{logtrace.FieldModule: "p2p", logtrace.FieldError: err.Error(), "node_id": string(nodeID)}) } return nil @@ -127,30 +127,30 @@ func (s *DHT) updateLastReplicated(ctx context.Context, nodeID []byte, timestamp func (s *DHT) Replicate(ctx context.Context) { historicStart, err := s.store.GetOwnCreatedAt(ctx) if err != nil { - log.WithContext(ctx).WithError(err).Error("unable to get own createdAt") + logtrace.Error(ctx, "unable to get own createdAt", logtrace.Fields{logtrace.FieldError: err.Error()}) historicStart = time.Now().UTC().Add(-24 * time.Hour * 180) } - log.P2P().WithContext(ctx).WithField("historic-start", historicStart).Info("replicating data") + logtrace.Info(ctx, "replicating data", logtrace.Fields{logtrace.FieldModule: "p2p", "historic-start": historicStart}) for i := 0; i < B; i++ { if time.Since(s.ht.refreshTime(i)) > defaultRefreshTime { // refresh the bucket by iterative find node id := s.ht.randomIDFromBucket(K) if _, err := s.iterate(ctx, IterateFindNode, id, nil, 0); err != nil { - log.P2P().WithContext(ctx).WithError(err).Error("replicate iterate find node failed") + logtrace.Error(ctx, "replicate iterate find node failed", logtrace.Fields{logtrace.FieldModule: "p2p", logtrace.FieldError: err.Error()}) } } } repInfo, err := s.store.GetAllReplicationInfo(ctx) if err != nil { - log.P2P().WithContext(ctx).WithError(err).Errorf("get all replicationInfo failed") + logtrace.Error(ctx, "get all replicationInfo failed", logtrace.Fields{logtrace.FieldModule: "p2p", logtrace.FieldError: err.Error()}) return } if len(repInfo) == 0 { - log.P2P().WithContext(ctx).Info("no replication info found") + logtrace.Info(ctx, "no replication info found", logtrace.Fields{logtrace.FieldModule: "p2p"}) return } @@ -159,7 +159,7 @@ func (s *DHT) Replicate(ctx context.Context) { from = *repInfo[0].LastReplicatedAt } - log.P2P().WithContext(ctx).WithField("from", from).Info("getting all possible replication keys") + logtrace.Info(ctx, "getting all possible replication keys", logtrace.Fields{logtrace.FieldModule: "p2p", "from": from}) to := time.Now().UTC() replicationKeys := s.store.GetKeysForReplication(ctx, from, to) @@ -180,8 +180,6 @@ func (s *DHT) Replicate(ctx context.Context) { continue } - logEntry := log.P2P().WithContext(ctx).WithField("rep-ip", info.IP).WithField("rep-id", string(info.ID)) - start := historicStart if info.LastReplicatedAt != nil { start = *info.LastReplicatedAt @@ -191,15 +189,15 @@ func (s *DHT) Replicate(ctx context.Context) { if idx == -1 { // Now closestContactKeys contains all the keys that are in the closest contacts. if err := s.updateLastReplicated(ctx, info.ID, to); err != nil { - logEntry.Error("replicate update lastReplicated failed") + logtrace.Error(ctx, "replicate update lastReplicated failed", logtrace.Fields{logtrace.FieldModule: "p2p", "rep-ip": info.IP, "rep-id": string(info.ID)}) } else { - logEntry.WithField("node", info.IP).WithField("to", to.String()).WithField("fetch-keys", 0).Debug("no replication keys - replicate update lastReplicated success") + logtrace.Debug(ctx, "no replication keys - replicate update lastReplicated success", logtrace.Fields{logtrace.FieldModule: "p2p", "node": info.IP, "to": to.String(), "fetch-keys": 0}) } continue } countToSendKeys := len(replicationKeys) - idx - logEntry.WithField("len-rep-keys", countToSendKeys).Info("count of replication keys to be checked") + logtrace.Info(ctx, "count of replication keys to be checked", logtrace.Fields{logtrace.FieldModule: "p2p", "rep-ip": info.IP, "rep-id": string(info.ID), "len-rep-keys": countToSendKeys}) // Preallocate a slice with a capacity equal to the number of keys. closestContactKeys := make([]string, 0, countToSendKeys) @@ -212,13 +210,13 @@ func (s *DHT) Replicate(ctx context.Context) { } } - logEntry.WithField("len-rep-keys", len(closestContactKeys)).Info("closest contact keys count") + logtrace.Info(ctx, "closest contact keys count", logtrace.Fields{logtrace.FieldModule: "p2p", "rep-ip": info.IP, "rep-id": string(info.ID), "len-rep-keys": len(closestContactKeys)}) if len(closestContactKeys) == 0 { if err := s.updateLastReplicated(ctx, info.ID, to); err != nil { - logEntry.Error("replicate update lastReplicated failed") + logtrace.Error(ctx, "replicate update lastReplicated failed", logtrace.Fields{logtrace.FieldModule: "p2p", "rep-ip": info.IP, "rep-id": string(info.ID)}) } else { - logEntry.WithField("node", info.IP).WithField("to", to.String()).WithField("closest-contact-keys", 0).Info("no closest keys found - replicate update lastReplicated success") + logtrace.Info(ctx, "no closest keys found - replicate update lastReplicated success", logtrace.Fields{logtrace.FieldModule: "p2p", "node": info.IP, "to": to.String(), "closest-contact-keys": 0}) } continue @@ -246,31 +244,29 @@ func (s *DHT) Replicate(ctx context.Context) { return nil }, b, func(err error, duration time.Duration) { - logEntry.WithError(err).WithField("duration", duration).Error("retrying send replicate data") + logtrace.Error(ctx, "retrying send replicate data", logtrace.Fields{logtrace.FieldModule: "p2p", logtrace.FieldError: err.Error(), "rep-ip": info.IP, "rep-id": string(info.ID), "duration": duration}) }) if err != nil { - logEntry.WithError(err).Error("send replicate data failed after retries") + logtrace.Error(ctx, "send replicate data failed after retries", logtrace.Fields{logtrace.FieldModule: "p2p", logtrace.FieldError: err.Error(), "rep-ip": info.IP, "rep-id": string(info.ID)}) continue } // Now closestContactKeys contains all the keys that are in the closest contacts. if err := s.updateLastReplicated(ctx, info.ID, to); err != nil { - logEntry.Error("replicate update lastReplicated failed") + logtrace.Error(ctx, "replicate update lastReplicated failed", logtrace.Fields{logtrace.FieldModule: "p2p", "rep-ip": info.IP, "rep-id": string(info.ID)}) } else { - logEntry.WithField("node", info.IP).WithField("to", to.String()).WithField("expected-rep-keys", len(closestContactKeys)).Info("replicate update lastReplicated success") + logtrace.Info(ctx, "replicate update lastReplicated success", logtrace.Fields{logtrace.FieldModule: "p2p", "node": info.IP, "to": to.String(), "expected-rep-keys": len(closestContactKeys)}) } } - log.P2P().WithContext(ctx).Info("Replication done") + logtrace.Info(ctx, "Replication done", logtrace.Fields{logtrace.FieldModule: "p2p"}) } func (s *DHT) adjustNodeKeys(ctx context.Context, from time.Time, info domain.NodeReplicationInfo) error { replicationKeys := s.store.GetKeysForReplication(ctx, from, time.Now().UTC()) - logEntry := log.P2P().WithContext(ctx).WithField("offline-node-ip", info.IP).WithField("offline-node-id", string(info.ID)). - WithField("total-rep-keys", len(replicationKeys)) - logEntry.WithField("from", from.String()).Info("begin adjusting node keys process for offline node") + logtrace.Info(ctx, "begin adjusting node keys process for offline node", logtrace.Fields{logtrace.FieldModule: "p2p", "offline-node-ip": info.IP, "offline-node-id": string(info.ID), "total-rep-keys": len(replicationKeys), "from": from.String()}) // prepare ignored nodes list but remove the node we are adjusting // because we want to find if this node was supposed to hold this key @@ -317,11 +313,11 @@ func (s *DHT) adjustNodeKeys(ctx context.Context, from time.Time, info domain.No failureCount := 0 for nodeInfoKey, keys := range nodeKeysMap { - logEntry.WithField("adjust-to-node", nodeInfoKey).WithField("to-adjust-keys-len", len(keys)).Info("sending adjusted replication keys to node") + logtrace.Info(ctx, "sending adjusted replication keys to node", logtrace.Fields{logtrace.FieldModule: "p2p", "offline-node-ip": info.IP, "offline-node-id": string(info.ID), "adjust-to-node": nodeInfoKey, "to-adjust-keys-len": len(keys)}) // Retrieve the node object from the key node, err := getNodeFromKey(nodeInfoKey) if err != nil { - logEntry.WithError(err).Error("Failed to parse node info from key") + logtrace.Error(ctx, "Failed to parse node info from key", logtrace.Fields{logtrace.FieldModule: "p2p", logtrace.FieldError: err.Error(), "offline-node-ip": info.IP, "offline-node-id": string(info.ID)}) return fmt.Errorf("failed to parse node info from key: %w", err) } @@ -346,11 +342,11 @@ func (s *DHT) adjustNodeKeys(ctx context.Context, from time.Time, info domain.No successCount++ return nil }, b, func(err error, duration time.Duration) { - logEntry.WithError(err).WithField("duration", duration).Error("retrying send replicate data") + logtrace.Error(ctx, "retrying send replicate data", logtrace.Fields{logtrace.FieldModule: "p2p", logtrace.FieldError: err.Error(), "offline-node-ip": info.IP, "offline-node-id": string(info.ID), "duration": duration}) }) if err != nil { - logEntry.WithError(err).Error("send replicate data failed after retries") + logtrace.Error(ctx, "send replicate data failed after retries", logtrace.Fields{logtrace.FieldModule: "p2p", logtrace.FieldError: err.Error(), "offline-node-ip": info.IP, "offline-node-id": string(info.ID)}) failureCount++ } } @@ -372,14 +368,14 @@ func (s *DHT) adjustNodeKeys(ctx context.Context, from time.Time, info domain.No return fmt.Errorf("replicate update isAdjusted failed: %v", err) } - logEntry.Info("offline node was successfully adjusted") + logtrace.Info(ctx, "offline node was successfully adjusted", logtrace.Fields{logtrace.FieldModule: "p2p", "offline-node-ip": info.IP, "offline-node-id": string(info.ID)}) return nil } func isNodeGoneAndShouldBeAdjusted(lastSeen *time.Time, isAlreadyAdjusted bool) bool { if lastSeen == nil { - log.Info("lastSeen is nil - aborting node adjustment") + logtrace.Info(context.Background(), "lastSeen is nil - aborting node adjustment", logtrace.Fields{}) return false } @@ -387,22 +383,21 @@ func isNodeGoneAndShouldBeAdjusted(lastSeen *time.Time, isAlreadyAdjusted bool) } func (s *DHT) checkAndAdjustNode(ctx context.Context, info domain.NodeReplicationInfo, start time.Time) { - logEntry := log.P2P().WithContext(ctx).WithField("rep-ip", info.IP).WithField("rep-id", string(info.ID)) adjustNodeKeys := isNodeGoneAndShouldBeAdjusted(info.LastSeen, info.IsAdjusted) if adjustNodeKeys { if err := s.adjustNodeKeys(ctx, start, info); err != nil { - logEntry.WithError(err).Error("failed to adjust node keys") + logtrace.Error(ctx, "failed to adjust node keys", logtrace.Fields{logtrace.FieldModule: "p2p", logtrace.FieldError: err.Error(), "rep-ip": info.IP, "rep-id": string(info.ID)}) } else { info.IsAdjusted = true info.UpdatedAt = time.Now().UTC() if err := s.store.UpdateIsAdjusted(ctx, string(info.ID), true); err != nil { - logEntry.WithError(err).Error("failed to update replication info, set isAdjusted to true") + logtrace.Error(ctx, "failed to update replication info, set isAdjusted to true", logtrace.Fields{logtrace.FieldModule: "p2p", logtrace.FieldError: err.Error(), "rep-ip": info.IP, "rep-id": string(info.ID)}) } else { - logEntry.Info("set isAdjusted to true") + logtrace.Info(ctx, "set isAdjusted to true", logtrace.Fields{logtrace.FieldModule: "p2p", "rep-ip": info.IP, "rep-id": string(info.ID)}) } } } - logEntry.Info("replication node not active, skipping over it.") + logtrace.Info(ctx, "replication node not active, skipping over it.", logtrace.Fields{logtrace.FieldModule: "p2p", "rep-ip": info.IP, "rep-id": string(info.ID)}) } diff --git a/p2p/kademlia/rq_symbols.go b/p2p/kademlia/rq_symbols.go index ed37ad61..0352d7de 100644 --- a/p2p/kademlia/rq_symbols.go +++ b/p2p/kademlia/rq_symbols.go @@ -6,7 +6,7 @@ import ( "sort" "time" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" "github.com/LumeraProtocol/supernode/pkg/utils" ) @@ -16,16 +16,16 @@ const ( ) func (s *DHT) startStoreSymbolsWorker(ctx context.Context) { - log.P2P().WithContext(ctx).Info("start delete data worker") + logtrace.Info(ctx, "start delete data worker", logtrace.Fields{logtrace.FieldModule: "p2p"}) for { select { case <-time.After(defaultSoreSymbolsInterval): if err := s.storeSymbols(ctx); err != nil { - log.P2P().WithContext(ctx).WithError(err).Error("store symbols") + logtrace.Error(ctx, "store symbols", logtrace.Fields{logtrace.FieldModule: "p2p", logtrace.FieldError: err}) } case <-ctx.Done(): - log.P2P().WithContext(ctx).Error("closing store symbols worker") + logtrace.Error(ctx, "closing store symbols worker", logtrace.Fields{logtrace.FieldModule: "p2p"}) return } } @@ -38,12 +38,12 @@ func (s *DHT) storeSymbols(ctx context.Context) error { } for _, dir := range dirs { - log.WithContext(ctx).WithField("dir", dir).WithField("txid", dir.TXID).Info("rq_symbols worker: start scanning dir & storing raptorQ symbols") + logtrace.Info(ctx, "rq_symbols worker: start scanning dir & storing raptorQ symbols", logtrace.Fields{"dir": dir, "txid": dir.TXID}) if err := s.scanDirAndStoreSymbols(ctx, dir.Dir, dir.TXID); err != nil { - log.P2P().WithContext(ctx).WithError(err).Error("scan and store symbols") + logtrace.Error(ctx, "scan and store symbols", logtrace.Fields{logtrace.FieldModule: "p2p", logtrace.FieldError: err}) } - log.WithContext(ctx).WithField("dir", dir).WithField("txid", dir.TXID).Info("rq_symbols worker: scanned dir & stored raptorQ symbols") + logtrace.Info(ctx, "rq_symbols worker: scanned dir & stored raptorQ symbols", logtrace.Fields{"dir": dir, "txid": dir.TXID}) } return nil @@ -66,11 +66,7 @@ func (s *DHT) scanDirAndStoreSymbols(ctx context.Context, dir, txid string) erro } sort.Strings(keys) - log.WithContext(ctx). - WithField("txid", txid). - WithField("dir", dir). - WithField("total", len(keys)). - Info("p2p-worker: storing ALL RaptorQ symbols") + logtrace.Info(ctx, "p2p-worker: storing ALL RaptorQ symbols", logtrace.Fields{"txid": txid, "dir": dir, "total": len(keys)}) // Batch-flush at loadSymbolsBatchSize for start := 0; start < len(keys); { diff --git a/p2p/kademlia/store/cloud.go/cloud.go b/p2p/kademlia/store/cloud.go/cloud.go index dd3a17e4..365f0542 100644 --- a/p2p/kademlia/store/cloud.go/cloud.go +++ b/p2p/kademlia/store/cloud.go/cloud.go @@ -2,13 +2,14 @@ package cloud import ( "bytes" + "context" "fmt" "os" "os/exec" "path/filepath" "sync" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" "github.com/google/uuid" ) @@ -30,12 +31,14 @@ type Storage interface { type RcloneStorage struct { bucketName string specName string + ctx context.Context } func NewRcloneStorage(bucketName, specName string) *RcloneStorage { return &RcloneStorage{ bucketName: bucketName, specName: specName, + ctx: context.Background(), } } @@ -44,7 +47,7 @@ func (r *RcloneStorage) Store(key string, data []byte) (string, error) { // Write data to a temporary file using os.WriteFile if err := os.WriteFile(filePath, data, 0644); err != nil { - log.WithField("filePath", filePath).WithError(err).Error("Failed to write data to file") + logtrace.Error(r.ctx, "Failed to write data to file", logtrace.Fields{"filePath": filePath, logtrace.FieldError: err}) return "", fmt.Errorf("failed to write data to file: %w", err) } @@ -57,14 +60,14 @@ func (r *RcloneStorage) Store(key string, data []byte) (string, error) { cmdOutput := &bytes.Buffer{} cmd.Stderr = cmdOutput // Capture standard error if err := cmd.Run(); err != nil { - log.WithField("key", key).WithError(err).Error("rclone command failed to upload file") + logtrace.Error(r.ctx, "rclone command failed to upload file", logtrace.Fields{"key": key, logtrace.FieldError: err}) return "", fmt.Errorf("rclone command failed: %s, error: %w", cmdOutput.String(), err) } // Delete the local file after successful upload go func() { if err := os.Remove(filePath); err != nil { - log.WithField("filePath", filePath).WithError(err).Error("Failed to delete local file after upload") + logtrace.Error(r.ctx, "Failed to delete local file after upload", logtrace.Fields{"filePath": filePath, logtrace.FieldError: err}) } }() @@ -84,7 +87,7 @@ func (r *RcloneStorage) Upload(key string, data []byte) (string, error) { cmd.Stdin = bytes.NewReader(data) // Provide data as stdin if err := cmd.Run(); err != nil { - log.WithField("remotePath", remotePath).Errorf("rclone command failed to upload file:%s", cmdOutput.String()) + logtrace.Error(r.ctx, fmt.Sprintf("rclone command failed to upload file:%s", cmdOutput.String()), logtrace.Fields{"remotePath": remotePath}) return "", fmt.Errorf("rclone command failed: %s, error: %w", cmdOutput.String(), err) } @@ -101,7 +104,7 @@ func (r *RcloneStorage) Fetch(key string) ([]byte, error) { cmd.Stderr = cmdOutput // Capture standard error err := cmd.Run() if err != nil { - log.WithField("key", key).WithError(err).Errorf("rclone command failed to fetch file:%s", cmdOutput.String()) + logtrace.Error(r.ctx, fmt.Sprintf("rclone command failed to fetch file:%s", cmdOutput.String()), logtrace.Fields{"key": key, logtrace.FieldError: err}) return nil, fmt.Errorf("rclone command failed: %s, error: %w", cmdOutput.String(), err) } @@ -216,7 +219,7 @@ func (r *RcloneStorage) Delete(key string) error { // Execute the command err := cmd.Run() if err != nil { - log.WithField("key", key).WithError(err).Errorf("rclone command failed to delete file:%s", cmdOutput.String()) + logtrace.Error(r.ctx, fmt.Sprintf("rclone command failed to delete file:%s", cmdOutput.String()), logtrace.Fields{"key": key, logtrace.FieldError: err}) return fmt.Errorf("rclone command failed: %s, error: %w", cmdOutput.String(), err) } @@ -271,7 +274,7 @@ func (r *RcloneStorage) DeleteBatch(keys []string) error { cmd.Stderr = cmdOutput // Capture standard error if err := cmd.Run(); err != nil { - log.WithField("key", key).WithError(err).Errorf("rclone command failed to delete file:%s", cmdOutput.String()) + logtrace.Error(r.ctx, fmt.Sprintf("rclone command failed to delete file:%s", cmdOutput.String()), logtrace.Fields{"key": key, logtrace.FieldError: err}) mu.Lock() if lastError == nil { lastError = fmt.Errorf("failed to delete some files") diff --git a/p2p/kademlia/store/meta/meta.go b/p2p/kademlia/store/meta/meta.go index 0ef444c1..fb1679f6 100644 --- a/p2p/kademlia/store/meta/meta.go +++ b/p2p/kademlia/store/meta/meta.go @@ -10,7 +10,7 @@ import ( "github.com/LumeraProtocol/supernode/p2p/kademlia/domain" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" "database/sql" @@ -67,7 +67,7 @@ func NewStore(ctx context.Context, dataDir string) (*Store, error) { quit: make(chan bool), } - log.P2P().WithContext(ctx).Infof("p2p data dir: %v", dataDir) + logtrace.Info(ctx, fmt.Sprintf("p2p data dir: %v", dataDir), logtrace.Fields{logtrace.FieldModule: "p2p"}) if _, err := os.Stat(dataDir); os.IsNotExist(err) { if err := os.MkdirAll(dataDir, 0750); err != nil { return nil, fmt.Errorf("mkdir %q: %w", dataDir, err) @@ -97,7 +97,7 @@ func NewStore(ctx context.Context, dataDir string) (*Store, error) { } if err := s.migrateToDelKeys(); err != nil { - log.P2P().WithContext(ctx).Errorf("cannot create to-del-keys table in sqlite database: %s", err.Error()) + logtrace.Error(ctx, fmt.Sprintf("cannot create to-del-keys table in sqlite database: %s", err.Error()), logtrace.Fields{logtrace.FieldModule: "p2p"}) } pragmas := []string{ @@ -174,7 +174,7 @@ func (s *Store) startCheckpointWorker(ctx context.Context) { } return err }, b, func(err error, duration time.Duration) { - log.WithContext(ctx).WithField("duration", duration).Error("Failed to perform checkpoint, retrying...") + logtrace.Error(ctx, "Failed to perform checkpoint, retrying...", logtrace.Fields{"duration": duration}) }) if err == nil { @@ -185,10 +185,10 @@ func (s *Store) startCheckpointWorker(ctx context.Context) { select { case <-ctx.Done(): - log.WithContext(ctx).Info("Stopping checkpoint worker because of context cancel") + logtrace.Info(ctx, "Stopping checkpoint worker because of context cancel", logtrace.Fields{}) return case <-s.worker.quit: - log.WithContext(ctx).Info("Stopping checkpoint worker because of quit signal") + logtrace.Info(ctx, "Stopping checkpoint worker because of quit signal", logtrace.Fields{}) return default: } @@ -201,13 +201,13 @@ func (s *Store) start(ctx context.Context) { select { case job := <-s.worker.JobQueue: if err := s.performJob(job); err != nil { - log.WithError(err).Error("Failed to perform job") + logtrace.Error(ctx, "Failed to perform job", logtrace.Fields{logtrace.FieldError: err}) } case <-s.worker.quit: - log.Info("exit sqlite meta db worker - quit signal received") + logtrace.Info(ctx, "exit sqlite meta db worker - quit signal received", logtrace.Fields{}) return case <-ctx.Done(): - log.Info("exit sqlite meta db worker- ctx done signal received") + logtrace.Info(ctx, "exit sqlite meta db worker- ctx done signal received", logtrace.Fields{}) return } } @@ -227,7 +227,7 @@ func (s *Store) Store(ctx context.Context, key []byte) error { Key: key, } - if val := ctx.Value(log.TaskIDKey); val != nil { + if val := ctx.Value(logtrace.CorrelationIDKey); val != nil { switch val := val.(type) { case string: job.TaskID = val @@ -249,7 +249,7 @@ func (s *Store) performJob(j Job) error { case "Insert": err := s.storeDisabledKey(j.Key) if err != nil { - log.WithError(err).WithField("taskID", j.TaskID).WithField("id", j.ReqID).Error("failed to store disable key record") + logtrace.Error(context.Background(), "failed to store disable key record", logtrace.Fields{logtrace.FieldError: err, logtrace.FieldTaskID: j.TaskID, "id": j.ReqID}) return fmt.Errorf("failed to store disable key record: %w", err) } case "Delete": @@ -274,7 +274,7 @@ func (s *Store) Close(ctx context.Context) { if s.db != nil { if err := s.db.Close(); err != nil { - log.P2P().WithContext(ctx).Errorf("Failed to close database: %s", err) + logtrace.Error(ctx, fmt.Sprintf("Failed to close database: %s", err), logtrace.Fields{logtrace.FieldModule: "p2p"}) } } } @@ -310,13 +310,13 @@ func (s *Store) deleteRecord(key []byte) { res, err := s.db.Exec("DELETE FROM disabled_keys WHERE key = ?", hkey) if err != nil { - log.P2P().Debugf("cannot delete disabled keys record by key %s: %v", hkey, err) + logtrace.Debug(context.Background(), fmt.Sprintf("cannot delete disabled keys record by key %s: %v", hkey, err), logtrace.Fields{logtrace.FieldModule: "p2p"}) } if rowsAffected, err := res.RowsAffected(); err != nil { - log.P2P().Debugf("failed to delete disabled key record by key %s: %v", hkey, err) + logtrace.Debug(context.Background(), fmt.Sprintf("failed to delete disabled key record by key %s: %v", hkey, err), logtrace.Fields{logtrace.FieldModule: "p2p"}) } else if rowsAffected == 0 { - log.P2P().Debugf("failed to delete disabled key record by key %s", hkey) + logtrace.Debug(context.Background(), fmt.Sprintf("failed to delete disabled key record by key %s", hkey), logtrace.Fields{logtrace.FieldModule: "p2p"}) } } diff --git a/p2p/kademlia/store/sqlite/meta_worker.go b/p2p/kademlia/store/sqlite/meta_worker.go index 8a94ed25..d9c7d1ad 100644 --- a/p2p/kademlia/store/sqlite/meta_worker.go +++ b/p2p/kademlia/store/sqlite/meta_worker.go @@ -11,9 +11,9 @@ import ( "sync" "time" - "github.com/LumeraProtocol/supernode/pkg/log" - "github.com/LumeraProtocol/supernode/pkg/utils" "github.com/LumeraProtocol/supernode/p2p/kademlia/store/cloud.go" + "github.com/LumeraProtocol/supernode/pkg/logtrace" + "github.com/LumeraProtocol/supernode/pkg/utils" "github.com/jmoiron/sqlx" _ "github.com/mattn/go-sqlite3" ) @@ -80,12 +80,12 @@ func NewMigrationMetaStore(ctx context.Context, dataDir string, cloud cloud.Stor db.SetMaxIdleConns(10) if err := setPragmas(db); err != nil { - log.WithContext(ctx).WithError(err).Error("error executing pragmas") + logtrace.Error(ctx, "error executing pragmas", logtrace.Fields{logtrace.FieldError: err}) } p2pDataStore, err := connectP2PDataStore(dataDir) if err != nil { - log.WithContext(ctx).WithError(err).Error("error connecting p2p store from meta-migration store") + logtrace.Error(ctx, "error connecting p2p store from meta-migration store", logtrace.Fields{logtrace.FieldError: err}) } handler := &MigrationMetaStore{ @@ -98,15 +98,15 @@ func NewMigrationMetaStore(ctx context.Context, dataDir string, cloud cloud.Stor } if err := handler.migrateMeta(); err != nil { - log.P2P().WithContext(ctx).Errorf("cannot create meta table in sqlite database: %s", err.Error()) + logtrace.Error(ctx, "cannot create meta table in sqlite database", logtrace.Fields{logtrace.FieldError: err, logtrace.FieldModule: "p2p"}) } if err := handler.migrateMetaMigration(); err != nil { - log.P2P().WithContext(ctx).Errorf("cannot create meta-migration table in sqlite database: %s", err.Error()) + logtrace.Error(ctx, "cannot create meta-migration table in sqlite database", logtrace.Fields{logtrace.FieldError: err, logtrace.FieldModule: "p2p"}) } if err := handler.migrateMigration(); err != nil { - log.P2P().WithContext(ctx).Errorf("cannot create migration table in sqlite database: %s", err.Error()) + logtrace.Error(ctx, "cannot create migration table in sqlite database", logtrace.Fields{logtrace.FieldError: err, logtrace.FieldModule: "p2p"}) } go func() { @@ -114,7 +114,7 @@ func NewMigrationMetaStore(ctx context.Context, dataDir string, cloud cloud.Stor handler.isSyncInProgress = true err := handler.syncMetaWithData(ctx) if err != nil { - log.WithContext(ctx).WithError(err).Error("error syncing meta with p2p data") + logtrace.Error(ctx, "error syncing meta with p2p data", logtrace.Fields{logtrace.FieldError: err}) } handler.isSyncInProgress = false @@ -124,7 +124,7 @@ func NewMigrationMetaStore(ctx context.Context, dataDir string, cloud cloud.Stor go handler.startLastAccessedUpdateWorker(ctx) go handler.startInsertWorker(ctx) go handler.startMigrationExecutionWorker(ctx) - log.WithContext(ctx).Info("MigrationMetaStore workers started") + logtrace.Info(ctx, "MigrationMetaStore workers started", logtrace.Fields{}) return handler, nil } @@ -237,14 +237,14 @@ func (d *MigrationMetaStore) syncMetaWithData(ctx context.Context) error { for continueProcessing { rows, err := d.p2pDataStore.Queryx(query, metaSyncBatchSize, offset) if err != nil { - log.WithContext(ctx).WithError(err).Error("error querying p2p data store") + logtrace.Error(ctx, "error querying p2p data store", logtrace.Fields{logtrace.FieldError: err}) break } tx, err := d.db.Beginx() if err != nil { rows.Close() - log.WithContext(ctx).WithError(err).Error("failed to start transaction") + logtrace.Error(ctx, "failed to start transaction", logtrace.Fields{logtrace.FieldError: err}) continue } @@ -252,7 +252,7 @@ func (d *MigrationMetaStore) syncMetaWithData(ctx context.Context) error { if err != nil { tx.Rollback() rows.Close() - log.WithContext(ctx).WithError(err).Error("failed to prepare statement") + logtrace.Error(ctx, "failed to prepare statement", logtrace.Fields{logtrace.FieldError: err}) continue } @@ -262,7 +262,7 @@ func (d *MigrationMetaStore) syncMetaWithData(ctx context.Context) error { var t *time.Time if err := rows.Scan(&r.Key, &r.Data, &t); err != nil { - log.WithContext(ctx).WithError(err).Error("error scanning row from p2p data store") + logtrace.Error(ctx, "error scanning row from p2p data store", logtrace.Fields{logtrace.FieldError: err}) continue } if t != nil { @@ -270,7 +270,7 @@ func (d *MigrationMetaStore) syncMetaWithData(ctx context.Context) error { } if _, err := stmt.Exec(r.Key, r.UpdatedAt, len(r.Data)); err != nil { - log.WithContext(ctx).WithField("key", r.Key).WithError(err).Error("error inserting key to meta") + logtrace.Error(ctx, "error inserting key to meta", logtrace.Fields{"key": r.Key, logtrace.FieldError: err}) continue } @@ -278,12 +278,12 @@ func (d *MigrationMetaStore) syncMetaWithData(ctx context.Context) error { } if err := rows.Err(); err != nil { - log.WithContext(ctx).WithError(err).Error("error iterating rows") + logtrace.Error(ctx, "error iterating rows", logtrace.Fields{logtrace.FieldError: err}) } if recordsProcessed > 0 { if err := tx.Commit(); err != nil { - log.WithContext(ctx).WithError(err).Error("Failed to commit transaction") + logtrace.Error(ctx, "Failed to commit transaction", logtrace.Fields{logtrace.FieldError: err}) } } else { tx.Rollback() @@ -332,7 +332,7 @@ func PostAccessUpdate(updates []string) { }: // Inserted default: - log.WithContext(context.Background()).Error("updateChannel is full, dropping update") + logtrace.Error(context.Background(), "updateChannel is full, dropping update", logtrace.Fields{}) } } @@ -348,7 +348,7 @@ func (d *MigrationMetaStore) startLastAccessedUpdateWorker(ctx context.Context) case <-d.updateTicker.C: d.commitLastAccessedUpdates(ctx) case <-ctx.Done(): - log.WithContext(ctx).Info("Shutting down last accessed update worker") + logtrace.Info(ctx, "Shutting down last accessed update worker", logtrace.Fields{}) return } } @@ -359,12 +359,12 @@ func (d *MigrationMetaStore) commitLastAccessedUpdates(ctx context.Context) { d.updates.Range(func(key, value interface{}) bool { k, ok := key.(string) if !ok { - log.WithContext(ctx).Error("Error converting key to string (commitLastAccessedUpdates)") + logtrace.Error(ctx, "Error converting key to string (commitLastAccessedUpdates)", logtrace.Fields{}) return false } v, ok := value.(time.Time) if !ok { - log.WithContext(ctx).Error("Error converting value to time.Time (commitLastAccessedUpdates)") + logtrace.Error(ctx, "Error converting value to time.Time (commitLastAccessedUpdates)", logtrace.Fields{}) return false } keysToUpdate[k] = v @@ -378,7 +378,7 @@ func (d *MigrationMetaStore) commitLastAccessedUpdates(ctx context.Context) { tx, err := d.db.BeginTxx(ctx, nil) if err != nil { - log.WithContext(ctx).WithError(err).Error("Error starting transaction (commitLastAccessedUpdates)") + logtrace.Error(ctx, "Error starting transaction (commitLastAccessedUpdates)", logtrace.Fields{logtrace.FieldError: err}) return } @@ -391,7 +391,7 @@ func (d *MigrationMetaStore) commitLastAccessedUpdates(ctx context.Context) { access_count = access_count + 1`) if err != nil { tx.Rollback() // Roll back the transaction on error - log.WithContext(ctx).WithError(err).Error("Error preparing statement (commitLastAccessedUpdates)") + logtrace.Error(ctx, "Error preparing statement (commitLastAccessedUpdates)", logtrace.Fields{logtrace.FieldError: err}) return } defer stmt.Close() @@ -399,13 +399,13 @@ func (d *MigrationMetaStore) commitLastAccessedUpdates(ctx context.Context) { for k, v := range keysToUpdate { _, err := stmt.Exec(k, v) if err != nil { - log.WithContext(ctx).WithError(err).WithField("key", k).Error("Error executing statement (commitLastAccessedUpdates)") + logtrace.Error(ctx, "Error executing statement (commitLastAccessedUpdates)", logtrace.Fields{logtrace.FieldError: err, "key": k}) } } if err := tx.Commit(); err != nil { tx.Rollback() - log.WithContext(ctx).WithError(err).Error("Error committing transaction (commitLastAccessedUpdates)") + logtrace.Error(ctx, "Error committing transaction (commitLastAccessedUpdates)", logtrace.Fields{logtrace.FieldError: err}) return } @@ -414,7 +414,7 @@ func (d *MigrationMetaStore) commitLastAccessedUpdates(ctx context.Context) { d.updates.Delete(k) } - log.WithContext(ctx).WithField("count", len(keysToUpdate)).Info("Committed last accessed updates") + logtrace.Info(ctx, "Committed last accessed updates", logtrace.Fields{"count": len(keysToUpdate)}) } func PostKeysInsert(updates []UpdateMessage) { @@ -423,7 +423,7 @@ func PostKeysInsert(updates []UpdateMessage) { case insertChannel <- update: // Inserted default: - log.WithContext(context.Background()).Error("insertChannel is full, dropping update") + logtrace.Error(context.Background(), "insertChannel is full, dropping update", logtrace.Fields{}) } } } @@ -437,7 +437,7 @@ func (d *MigrationMetaStore) startInsertWorker(ctx context.Context) { case <-d.insertTicker.C: d.commitInserts(ctx) case <-ctx.Done(): - log.WithContext(ctx).Info("Shutting down insert meta keys worker") + logtrace.Info(ctx, "Shutting down insert meta keys worker", logtrace.Fields{}) d.commitInserts(ctx) return } @@ -449,12 +449,12 @@ func (d *MigrationMetaStore) commitInserts(ctx context.Context) { d.inserts.Range(func(key, value interface{}) bool { k, ok := key.(string) if !ok { - log.WithContext(ctx).Error("Error converting key to string (commitInserts)") + logtrace.Error(ctx, "Error converting key to string (commitInserts)", logtrace.Fields{}) return false } v, ok := value.(UpdateMessage) if !ok { - log.WithContext(ctx).Error("Error converting value to UpdateMessage (commitInserts)") + logtrace.Error(ctx, "Error converting value to UpdateMessage (commitInserts)", logtrace.Fields{}) return false } @@ -469,7 +469,7 @@ func (d *MigrationMetaStore) commitInserts(ctx context.Context) { tx, err := d.db.BeginTxx(ctx, nil) if err != nil { - log.WithContext(ctx).WithError(err).Error("Error starting transaction (commitInserts)") + logtrace.Error(ctx, "Error starting transaction (commitInserts)", logtrace.Fields{logtrace.FieldError: err}) return } @@ -477,7 +477,7 @@ func (d *MigrationMetaStore) commitInserts(ctx context.Context) { stmt, err := tx.Preparex("INSERT OR REPLACE INTO meta (key, last_accessed, access_count, data_size) VALUES (?, ?, ?, ?)") if err != nil { tx.Rollback() // Ensure to rollback in case of an error - log.WithContext(ctx).WithError(err).Error("Error preparing statement (commitInserts)") + logtrace.Error(ctx, "Error preparing statement (commitInserts)", logtrace.Fields{logtrace.FieldError: err}) return } defer stmt.Close() @@ -486,13 +486,13 @@ func (d *MigrationMetaStore) commitInserts(ctx context.Context) { accessCount := 1 _, err := stmt.Exec(k, v.LastAccessTime, accessCount, v.Size) if err != nil { - log.WithContext(ctx).WithError(err).WithField("key", k).Error("Error executing statement (commitInserts)") + logtrace.Error(ctx, "Error executing statement (commitInserts)", logtrace.Fields{logtrace.FieldError: err, "key": k}) } } if err := tx.Commit(); err != nil { tx.Rollback() // Rollback transaction if commit fails - log.WithContext(ctx).WithError(err).Error("Error committing transaction (commitInserts)") + logtrace.Error(ctx, "Error committing transaction (commitInserts)", logtrace.Fields{logtrace.FieldError: err}) return } @@ -501,7 +501,7 @@ func (d *MigrationMetaStore) commitInserts(ctx context.Context) { d.inserts.Delete(k) } - log.WithContext(ctx).WithField("count", len(keysToUpdate)).Info("Committed inserts") + logtrace.Info(ctx, "Committed inserts", logtrace.Fields{"count": len(keysToUpdate)}) } // startMigrationExecutionWorker starts the worker that executes a migration @@ -511,7 +511,7 @@ func (d *MigrationMetaStore) startMigrationExecutionWorker(ctx context.Context) case <-d.migrationExecutionTicker.C: d.checkAndExecuteMigration(ctx) case <-ctx.Done(): - log.WithContext(ctx).Info("Shutting down data migration worker") + logtrace.Info(ctx, "Shutting down data migration worker", logtrace.Fields{}) return } } @@ -536,7 +536,7 @@ func (d *MigrationMetaStore) checkAndExecuteMigration(ctx context.Context) { // Check the available disk space isLow, err := utils.CheckDiskSpace(lowSpaceThresholdGB) if err != nil { - log.WithContext(ctx).WithError(err).Error("migration worker: check disk space failed") + logtrace.Error(ctx, "migration worker: check disk space failed", logtrace.Fields{logtrace.FieldError: err}) } //if !isLow { @@ -544,23 +544,23 @@ func (d *MigrationMetaStore) checkAndExecuteMigration(ctx context.Context) { //return //} - log.WithContext(ctx).WithField("islow", isLow).Info("Starting data migration") + logtrace.Info(ctx, "Starting data migration", logtrace.Fields{"islow": isLow}) // Step 1: Fetch pending migrations var migrations Migrations err = d.db.Select(&migrations, `SELECT id FROM migration WHERE migration_started_at IS NULL or migration_finished_at IS NULL`) if err != nil { - log.WithContext(ctx).WithError(err).Error("Failed to fetch pending migrations") + logtrace.Error(ctx, "Failed to fetch pending migrations", logtrace.Fields{logtrace.FieldError: err}) return } - log.WithContext(ctx).WithField("count", len(migrations)).Info("Fetched pending migrations") + logtrace.Info(ctx, "Fetched pending migrations", logtrace.Fields{"count": len(migrations)}) // Iterate over each migration for _, migration := range migrations { - log.WithContext(ctx).WithField("migration_id", migration.ID).Info("Processing migration") + logtrace.Info(ctx, "Processing migration", logtrace.Fields{"migration_id": migration.ID}) if err := d.ProcessMigrationInBatches(ctx, migration); err != nil { - log.WithContext(ctx).WithError(err).WithField("migration_id", migration.ID).Error("Failed to process migration") + logtrace.Error(ctx, "Failed to process migration", logtrace.Fields{logtrace.FieldError: err, "migration_id": migration.ID}) continue } } @@ -579,7 +579,7 @@ func (d *MigrationMetaStore) ProcessMigrationInBatches(ctx context.Context, migr } if totalKeys < minKeysToMigrate { - log.WithContext(ctx).WithField("migration_id", migration.ID).WithField("keys-count", totalKeys).Info("Skipping migration due to insufficient keys") + logtrace.Info(ctx, "Skipping migration due to insufficient keys", logtrace.Fields{"migration_id": migration.ID, "keys-count": totalKeys}) return nil } @@ -612,7 +612,7 @@ func (d *MigrationMetaStore) ProcessMigrationInBatches(ctx context.Context, migr // Retrieve and upload data for current batch if err := d.processSingleBatch(ctx, batchKeys); err != nil { - log.WithContext(ctx).WithError(err).WithField("migration_id", migration.ID).WithField("batch-keys-count", len(batchKeys)).Error("Failed to process batch") + logtrace.Error(ctx, "Failed to process batch", logtrace.Fields{logtrace.FieldError: err, "migration_id": migration.ID, "batch-keys-count": len(batchKeys)}) return fmt.Errorf("failed to process batch: %w - exiting now", err) } } @@ -630,7 +630,7 @@ func (d *MigrationMetaStore) ProcessMigrationInBatches(ctx context.Context, migr } } - log.WithContext(ctx).WithField("migration_id", migration.ID).WithField("tota-keys-count", totalKeys).WithField("migrated_in_current_iteration", nonMigratedKeys).Info("Migration processed successfully") + logtrace.Info(ctx, "Migration processed successfully", logtrace.Fields{"migration_id": migration.ID, "tota-keys-count": totalKeys, "migrated_in_current_iteration": nonMigratedKeys}) return nil } @@ -666,24 +666,24 @@ func (d *MigrationMetaStore) uploadInBatches(ctx context.Context, keys []string, uploadedKeys, err := d.cloud.UploadBatch(batchKeys, batchData) if err != nil { - log.WithContext(ctx).WithError(err).Errorf("Failed to upload batch %d", i+1) + logtrace.Error(ctx, "Failed to upload batch", logtrace.Fields{logtrace.FieldError: err, "batch": i + 1}) lastError = err continue } if err := batchSetMigratedRecords(d.p2pDataStore, uploadedKeys); err != nil { - log.WithContext(ctx).WithError(err).Errorf("Failed to delete batch %d", i+1) + logtrace.Error(ctx, "Failed to delete batch", logtrace.Fields{logtrace.FieldError: err, "batch": i + 1}) lastError = err continue } if err := d.batchSetMigrated(uploadedKeys); err != nil { - log.WithContext(ctx).WithError(err).Errorf("Failed to batch is_migrated %d", i+1) + logtrace.Error(ctx, "Failed to batch is_migrated", logtrace.Fields{logtrace.FieldError: err, "batch": i + 1}) lastError = err continue } - log.WithContext(ctx).Infof("Successfully uploaded and deleted records for batch %d of %d", i+1, batches) + logtrace.Info(ctx, "Successfully uploaded and deleted records for batch", logtrace.Fields{"batch": i + 1, "total_batches": batches}) } return lastError @@ -822,7 +822,8 @@ func (d *MigrationMetaStore) InsertMetaMigrationData(ctx context.Context, migrat func (d *MigrationMetaStore) batchSetMigrated(keys []string) error { if len(keys) == 0 { - log.P2P().Info("no keys provided for batch update (is_migrated)") + // log.P2P().Info("no keys provided for batch update (is_migrated)") + logtrace.Info(context.Background(), "No keys provided for batch update (is_migrated)", logtrace.Fields{}) return nil } diff --git a/p2p/kademlia/store/sqlite/replication.go b/p2p/kademlia/store/sqlite/replication.go index 7065253b..486094ca 100644 --- a/p2p/kademlia/store/sqlite/replication.go +++ b/p2p/kademlia/store/sqlite/replication.go @@ -8,7 +8,7 @@ import ( "time" "github.com/LumeraProtocol/supernode/p2p/kademlia/domain" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" "github.com/cenkalti/backoff/v4" "github.com/jmoiron/sqlx" ) @@ -244,7 +244,9 @@ func (s *Store) GetKeysForReplication(ctx context.Context, from time.Time, to ti var results []domain.KeyWithTimestamp query := `SELECT key, createdAt FROM data WHERE createdAt > ? AND createdAt < ? ORDER BY createdAt ASC` if err := s.db.Select(&results, query, from, to); err != nil { - log.P2P().WithError(err).WithContext(ctx).Errorf("failed to get records for replication between %s and %s", from, to) + logtrace.Error(ctx, "failed to get records for replication", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error()}) return nil } @@ -478,7 +480,11 @@ func retrieveBatchValues(ctx context.Context, db *sqlx.DB, keys []string, getFro // Fetch from cloud cloudValues, err := s.cloud.FetchBatch(cloudKeys) if err != nil { - log.WithContext(ctx).WithError(err).Error("failed to fetch from cloud") + // log.WithContext(ctx).WithError(err).Error("failed to fetch from cloud") + logtrace.Error(ctx, "failed to fetch from cloud", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + }) } for key, value := range cloudValues { @@ -496,7 +502,11 @@ func retrieveBatchValues(ctx context.Context, db *sqlx.DB, keys []string, getFro // Store the fetched data in the local store if err := s.StoreBatch(ctx, datList, 0, false); err != nil { - log.WithError(err).Error("failed to store fetched data in local store") + // log.WithError(err).Error("failed to store fetched data in local store") + logtrace.Error(ctx, "failed to store fetched data in local store", logtrace.Fields{ + logtrace.FieldModule: "p2p", + logtrace.FieldError: err.Error(), + }) } }() } diff --git a/p2p/kademlia/store/sqlite/sqlite.go b/p2p/kademlia/store/sqlite/sqlite.go index 5a5bd1b5..917c9afc 100644 --- a/p2p/kademlia/store/sqlite/sqlite.go +++ b/p2p/kademlia/store/sqlite/sqlite.go @@ -11,7 +11,7 @@ import ( "time" "github.com/LumeraProtocol/supernode/p2p/kademlia/store/cloud.go" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" "github.com/LumeraProtocol/supernode/pkg/utils" "github.com/cenkalti/backoff/v4" @@ -74,7 +74,7 @@ func NewStore(ctx context.Context, dataDir string, cloud cloud.Storage, mst *Mig quit: make(chan bool), } - log.P2P().WithContext(ctx).Infof("p2p data dir: %v", dataDir) + logtrace.Info(ctx, "p2p data dir", logtrace.Fields{logtrace.FieldModule: "p2p", "data_dir": dataDir}) if _, err := os.Stat(dataDir); os.IsNotExist(err) { if err := os.MkdirAll(dataDir, 0750); err != nil { return nil, fmt.Errorf("mkdir %q: %w", dataDir, err) @@ -116,33 +116,33 @@ func NewStore(ctx context.Context, dataDir string, cloud cloud.Storage, mst *Mig } if err := s.ensureDatatypeColumn(); err != nil { - log.WithContext(ctx).WithError(err).Error("URGENT! unable to create datatype column in p2p database") + logtrace.Error(ctx, "URGENT! unable to create datatype column in p2p database", logtrace.Fields{logtrace.FieldError: err.Error()}) } if err := s.ensureAttempsColumn(); err != nil { - log.WithContext(ctx).WithError(err).Error("URGENT! unable to create attemps column in p2p database") + logtrace.Error(ctx, "URGENT! unable to create attemps column in p2p database", logtrace.Fields{logtrace.FieldError: err.Error()}) } if err := s.ensureIsOnCloudColumn(); err != nil { - log.WithContext(ctx).WithError(err).Error("URGENT! unable to create is_on_cloud column in p2p database") + logtrace.Error(ctx, "URGENT! unable to create is_on_cloud column in p2p database", logtrace.Fields{logtrace.FieldError: err.Error()}) } if err := s.ensureLastSeenColumn(); err != nil { - log.WithContext(ctx).WithError(err).Error("URGENT! unable to create datatype column in p2p database") + logtrace.Error(ctx, "URGENT! unable to create datatype column in p2p database", logtrace.Fields{logtrace.FieldError: err.Error()}) } - log.WithContext(ctx).Info("p2p database creating index on key column") + logtrace.Info(ctx, "p2p database creating index on key column", logtrace.Fields{logtrace.FieldModule: "p2p"}) _, err = db.Exec("CREATE INDEX IF NOT EXISTS idx_key ON data(key);") if err != nil { - log.WithContext(ctx).WithError(err).Error("URGENT! unable to create index on key column in p2p database") + logtrace.Error(ctx, "URGENT! unable to create index on key column in p2p database", logtrace.Fields{logtrace.FieldError: err.Error()}) } - log.WithContext(ctx).Info("p2p database created index on key column") + logtrace.Info(ctx, "p2p database created index on key column", logtrace.Fields{logtrace.FieldModule: "p2p"}) _, err = db.Exec("CREATE INDEX IF NOT EXISTS idx_createdat ON data(createdAt);") if err != nil { - log.WithContext(ctx).WithError(err).Error("URGENT! unable to create index on createdAt column in p2p database") + logtrace.Error(ctx, "URGENT! unable to create index on createdAt column in p2p database", logtrace.Fields{logtrace.FieldError: err.Error()}) } - log.WithContext(ctx).Info("p2p database created index on createdAt column") + logtrace.Info(ctx, "p2p database created index on createdAt column", logtrace.Fields{logtrace.FieldModule: "p2p"}) pragmas := []string{ "PRAGMA journal_mode=WAL;", @@ -283,7 +283,7 @@ func (s *Store) startCheckpointWorker(ctx context.Context) { } return err }, b, func(err error, duration time.Duration) { - log.WithContext(ctx).WithField("duration", duration).Error("Failed to perform checkpoint, retrying...") + logtrace.Error(ctx, "Failed to perform checkpoint, retrying...", logtrace.Fields{logtrace.FieldError: err.Error(), "duration": duration}) }) if err == nil { @@ -294,10 +294,10 @@ func (s *Store) startCheckpointWorker(ctx context.Context) { select { case <-ctx.Done(): - log.WithContext(ctx).Info("Stopping checkpoint worker because of context cancel") + logtrace.Info(ctx, "Stopping checkpoint worker because of context cancel", logtrace.Fields{}) return case <-s.worker.quit: - log.WithContext(ctx).Info("Stopping checkpoint worker because of quit signal") + logtrace.Info(ctx, "Stopping checkpoint worker because of quit signal", logtrace.Fields{}) return default: } @@ -310,13 +310,13 @@ func (s *Store) start(ctx context.Context) { select { case job := <-s.worker.JobQueue: if err := s.performJob(job); err != nil { - log.WithError(err).Error("Failed to perform job") + logtrace.Error(ctx, "Failed to perform job", logtrace.Fields{logtrace.FieldError: err.Error()}) } case <-s.worker.quit: - log.Info("exit sqlite db worker - quit signal received") + logtrace.Info(ctx, "exit sqlite db worker - quit signal received", logtrace.Fields{}) return case <-ctx.Done(): - log.Info("exit sqlite db worker- ctx done signal received") + logtrace.Info(ctx, "exit sqlite db worker- ctx done signal received", logtrace.Fields{}) return } } @@ -340,7 +340,7 @@ func (s *Store) Store(ctx context.Context, key []byte, value []byte, datatype in IsOriginal: isOriginal, } - if val := ctx.Value(log.TaskIDKey); val != nil { + if val := ctx.Value(logtrace.CorrelationIDKey); val != nil { switch val := val.(type) { case string: job.TaskID = val @@ -365,7 +365,7 @@ func (s *Store) StoreBatch(ctx context.Context, values [][]byte, datatype int, i IsOriginal: isOriginal, } - if val := ctx.Value(log.TaskIDKey); val != nil { + if val := ctx.Value(logtrace.CorrelationIDKey); val != nil { switch val := val.(type) { case string: job.TaskID = val @@ -473,22 +473,23 @@ func (s *Store) checkpoint() error { // PerformJob performs the job in the JobQueue func (s *Store) performJob(j Job) error { + ctx := context.Background() switch j.JobType { case "Insert": err := s.storeRecord(j.Key, j.Value, j.DataType, j.IsOriginal) if err != nil { - log.WithError(err).WithField("taskID", j.TaskID).WithField("id", j.ReqID).Error("failed to store record") + logtrace.Error(ctx, "failed to store record", logtrace.Fields{logtrace.FieldError: err.Error(), logtrace.FieldTaskID: j.TaskID, "id": j.ReqID}) return fmt.Errorf("failed to store record: %w", err) } case "BatchInsert": err := s.storeBatchRecord(j.Values, j.DataType, j.IsOriginal) if err != nil { - log.WithError(err).WithField("taskID", j.TaskID).WithField("id", j.ReqID).Error("failed to store batch records") + logtrace.Error(ctx, "failed to store batch records", logtrace.Fields{logtrace.FieldError: err.Error(), logtrace.FieldTaskID: j.TaskID, "id": j.ReqID}) return fmt.Errorf("failed to store batch record: %w", err) } - log.WithField("taskID", j.TaskID).WithField("id", j.ReqID).Info("successfully stored batch records") + logtrace.Info(ctx, "successfully stored batch records", logtrace.Fields{logtrace.FieldTaskID: j.TaskID, "id": j.ReqID}) case "Update": err := s.updateKeyReplication(j.Key, j.ReplicatedAt) if err != nil { @@ -610,17 +611,18 @@ func (s *Store) storeBatchRecord(values [][]byte, typ int, isOriginal bool) erro // deleteRecord a key/value pair from the Store func (s *Store) deleteRecord(key []byte) { + ctx := context.Background() hkey := hex.EncodeToString(key) res, err := s.db.Exec("DELETE FROM data WHERE key = ?", hkey) if err != nil { - log.P2P().Debugf("cannot delete record by key %s: %v", hkey, err) + logtrace.Debug(ctx, "cannot delete record by key", logtrace.Fields{logtrace.FieldModule: "p2p", "key": hkey, logtrace.FieldError: err.Error()}) } if rowsAffected, err := res.RowsAffected(); err != nil { - log.P2P().Debugf("failed to delete record by key %s: %v", hkey, err) + logtrace.Debug(ctx, "failed to delete record by key", logtrace.Fields{logtrace.FieldModule: "p2p", "key": hkey, logtrace.FieldError: err.Error()}) } else if rowsAffected == 0 { - log.P2P().Debugf("failed to delete record by key %s", hkey) + logtrace.Debug(ctx, "failed to delete record by key", logtrace.Fields{logtrace.FieldModule: "p2p", "key": hkey}) } } @@ -666,7 +668,7 @@ func (s *Store) Stats(ctx context.Context) (map[string]interface{}, error) { stats := map[string]interface{}{} fi, err := os.Stat(dbFilePath) if err != nil { - log.WithContext(ctx).WithError(err).Error("failed to get p2p db size") + logtrace.Error(ctx, "failed to get p2p db size", logtrace.Fields{logtrace.FieldError: err.Error()}) } else { stats["p2p_db_size"] = utils.BytesToMB(uint64(fi.Size())) } @@ -674,7 +676,7 @@ func (s *Store) Stats(ctx context.Context) (map[string]interface{}, error) { if count, err := s.Count(ctx); err == nil { stats["p2p_db_records_count"] = count } else { - log.WithContext(ctx).WithError(err).Error("failed to get p2p records count") + logtrace.Error(ctx, "failed to get p2p records count", logtrace.Fields{logtrace.FieldError: err.Error()}) } return stats, nil @@ -686,7 +688,7 @@ func (s *Store) Close(ctx context.Context) { if s.db != nil { if err := s.db.Close(); err != nil { - log.P2P().WithContext(ctx).Errorf("Failed to close database: %s", err) + logtrace.Error(ctx, "Failed to close database", logtrace.Fields{logtrace.FieldModule: "p2p", logtrace.FieldError: err.Error()}) } } } @@ -698,7 +700,7 @@ func (s *Store) GetOwnCreatedAt(ctx context.Context) (time.Time, error) { err := s.db.Get(&createdAtStr, query) if err != nil { - log.P2P().WithContext(ctx).WithError(err).Errorf("failed to get own createdAt") + logtrace.Error(ctx, "failed to get own createdAt", logtrace.Fields{logtrace.FieldModule: "p2p", logtrace.FieldError: err.Error()}) return time.Time{}, fmt.Errorf("failed to get own createdAt: %w", err) } @@ -717,7 +719,7 @@ func (s *Store) GetOwnCreatedAt(ctx context.Context) (time.Time, error) { if err != nil { created, err = time.Parse("2006-01-02 15:04:05", createdAtString) if err != nil { - log.P2P().WithContext(ctx).WithError(err).Errorf("failed to parse createdAt") + logtrace.Error(ctx, "failed to parse createdAt", logtrace.Fields{logtrace.FieldModule: "p2p", logtrace.FieldError: err.Error()}) return time.Time{}, fmt.Errorf("failed to parse createdAt: %w", err) } } @@ -730,11 +732,12 @@ func (s *Store) GetOwnCreatedAt(ctx context.Context) (time.Time, error) { // GetLocalKeys func func (s *Store) GetLocalKeys(from time.Time, to time.Time) ([]string, error) { var keys []string - log.Info("getting all keys for SC") + ctx := context.Background() + logtrace.Info(ctx, "getting all keys for SC", logtrace.Fields{}) if err := s.db.Select(&keys, `SELECT key FROM data WHERE createdAt > ? and createdAt < ?`, from, to); err != nil { return keys, fmt.Errorf("error reading all keys from database: %w", err) } - log.Info("got all keys for SC") + logtrace.Info(ctx, "got all keys for SC", logtrace.Fields{}) return keys, nil } @@ -746,7 +749,8 @@ func (s *Store) BatchDeleteRecords(keys []string) error { func batchDeleteRecords(db *sqlx.DB, keys []string) error { if len(keys) == 0 { - log.P2P().Info("no keys provided for batch delete") + ctx := context.Background() + logtrace.Info(ctx, "no keys provided for batch delete", logtrace.Fields{logtrace.FieldModule: "p2p"}) return nil } @@ -783,7 +787,7 @@ func stringArgsToInterface(args []string) []interface{} { func batchSetMigratedRecords(db *sqlx.DB, keys []string) error { if len(keys) == 0 { - log.P2P().Info("no keys provided for batch update (migrated)") + logtrace.Info(context.Background(), "no keys provided for batch update (migrated)", logtrace.Fields{logtrace.FieldModule: "p2p"}) return nil } diff --git a/p2p/p2p.go b/p2p/p2p.go index 62386735..d8136105 100644 --- a/p2p/p2p.go +++ b/p2p/p2p.go @@ -11,7 +11,7 @@ import ( "github.com/LumeraProtocol/supernode/p2p/kademlia/store/meta" "github.com/LumeraProtocol/supernode/p2p/kademlia/store/sqlite" "github.com/LumeraProtocol/supernode/pkg/errors" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" "github.com/LumeraProtocol/supernode/pkg/lumera" "github.com/LumeraProtocol/supernode/pkg/storage/rqstore" "github.com/LumeraProtocol/supernode/pkg/utils" @@ -62,9 +62,9 @@ func (s *p2p) Run(ctx context.Context) error { return err } - log.P2P().WithContext(ctx).WithError(err).Error("failed to run kadmelia, retrying.") + logtrace.Error(ctx, "failed to run kadmelia, retrying.", logtrace.Fields{logtrace.FieldModule: "p2p", logtrace.FieldError: err}) } else { - log.P2P().WithContext(ctx).Info("kadmelia started successfully") + logtrace.Info(ctx, "kadmelia started successfully", logtrace.Fields{logtrace.FieldModule: "p2p"}) return nil } } @@ -74,8 +74,7 @@ func (s *p2p) Run(ctx context.Context) error { // run the kademlia network func (s *p2p) run(ctx context.Context) error { - ctx = log.ContextWithPrefix(ctx, logPrefix) - log.P2P().WithContext(ctx).Info("Running kademlia network") + logtrace.Info(ctx, "Running kademlia network", logtrace.Fields{logtrace.FieldModule: "p2p"}) // configure the kademlia dht for p2p service if err := s.configure(ctx); err != nil { return errors.Errorf("configure kademlia dht: %w", err) @@ -86,13 +85,13 @@ func (s *p2p) run(ctx context.Context) error { // start the node for kademlia network if err := s.dht.Start(ctx); err != nil { - log.P2P().WithContext(ctx).WithError(err).Error("failed to start kademlia network") + logtrace.Error(ctx, "failed to start kademlia network", logtrace.Fields{logtrace.FieldModule: "p2p", logtrace.FieldError: err}) return errors.Errorf("start the kademlia network: %w", err) } if err := s.dht.ConfigureBootstrapNodes(ctx, s.config.BootstrapNodes); err != nil { - log.P2P().WithContext(ctx).WithError(err).Error("failed to configure bootstrap nodes") - log.P2P().WithContext(ctx).WithError(err).Error("failed to get bootstap ip") + logtrace.Error(ctx, "failed to configure bootstrap nodes", logtrace.Fields{logtrace.FieldModule: "p2p", logtrace.FieldError: err}) + logtrace.Error(ctx, "failed to get bootstap ip", logtrace.Fields{logtrace.FieldModule: "p2p", logtrace.FieldError: err}) } // join the kademlia network if bootstrap nodes is set @@ -103,7 +102,7 @@ func (s *p2p) run(ctx context.Context) error { } s.running = true - log.WithContext(ctx).Info("p2p service is started") + logtrace.Info(ctx, "p2p service is started", logtrace.Fields{}) // block until context is done <-ctx.Done() @@ -111,13 +110,12 @@ func (s *p2p) run(ctx context.Context) error { // stop the node for kademlia network s.dht.Stop(ctx) - log.WithContext(ctx).Info("p2p service is stopped") + logtrace.Info(ctx, "p2p service is stopped", logtrace.Fields{}) return nil } // Store store data into the kademlia network func (s *p2p) Store(ctx context.Context, data []byte, typ int) (string, error) { - ctx = log.ContextWithPrefix(ctx, logPrefix) if !s.running { return "", errors.New("p2p service is not running") @@ -128,7 +126,6 @@ func (s *p2p) Store(ctx context.Context, data []byte, typ int) (string, error) { // StoreBatch will store a batch of values with their Blake3 hash as the key func (s *p2p) StoreBatch(ctx context.Context, data [][]byte, typ int, taskID string) error { - ctx = log.ContextWithPrefix(ctx, logPrefix) if !s.running { return errors.New("p2p service is not running") @@ -139,7 +136,6 @@ func (s *p2p) StoreBatch(ctx context.Context, data [][]byte, typ int, taskID str // Retrieve retrive the data from the kademlia network func (s *p2p) Retrieve(ctx context.Context, key string, localOnly ...bool) ([]byte, error) { - ctx = log.ContextWithPrefix(ctx, logPrefix) if !s.running { return nil, errors.New("p2p service is not running") @@ -150,7 +146,6 @@ func (s *p2p) Retrieve(ctx context.Context, key string, localOnly ...bool) ([]by // BatchRetrieve retrive the data from the kademlia network func (s *p2p) BatchRetrieve(ctx context.Context, keys []string, reqCount int, txID string, localOnly ...bool) (map[string][]byte, error) { - ctx = log.ContextWithPrefix(ctx, logPrefix) if !s.running { return nil, errors.New("p2p service is not running") @@ -161,7 +156,6 @@ func (s *p2p) BatchRetrieve(ctx context.Context, keys []string, reqCount int, tx // Delete delete key in queries node func (s *p2p) Delete(ctx context.Context, key string) error { - ctx = log.ContextWithPrefix(ctx, logPrefix) if !s.running { return errors.New("p2p service is not running") @@ -203,9 +197,7 @@ func (s *p2p) NClosestNodes(ctx context.Context, n int, key string, ignores ...s ret = append(ret, string(node.ID)) } - log.WithContext(ctx).WithField("no_of_closest_nodes", n).WithField("file_hash", key). - WithField("closest_nodes", ret). - Debug("closest nodes retrieved") + logtrace.Debug(ctx, "closest nodes retrieved", logtrace.Fields{"no_of_closest_nodes": n, "file_hash": key, "closest_nodes": ret}) return ret } @@ -226,9 +218,7 @@ func (s *p2p) NClosestNodesWithIncludingNodeList(ctx context.Context, n int, key ret = append(ret, string(node.ID)) } - log.WithContext(ctx).WithField("no_of_closest_nodes", n).WithField("file_hash", key). - WithField("closest_nodes", ret). - Debug("closest nodes retrieved") + logtrace.Debug(ctx, "closest nodes retrieved", logtrace.Fields{"no_of_closest_nodes": n, "file_hash": key, "closest_nodes": ret}) return ret } @@ -287,7 +277,6 @@ func New(ctx context.Context, config *Config, lumeraClient lumera.Client, kr key // LocalStore store data into the kademlia network func (s *p2p) LocalStore(ctx context.Context, key string, data []byte) (string, error) { - ctx = log.ContextWithPrefix(ctx, logPrefix) if !s.running { return "", errors.New("p2p service is not running") @@ -338,7 +327,7 @@ func (s *p2p) GetLocalKeys(ctx context.Context, from *time.Time, to time.Time) ( for i := 0; i < len(keys); i++ { str, err := hex.DecodeString(keys[i]) if err != nil { - log.WithContext(ctx).WithField("key", keys[i]).Error("replicate failed to hex decode key") + logtrace.Error(ctx, "replicate failed to hex decode key", logtrace.Fields{"key": keys[i]}) continue } diff --git a/pkg/common/task/state/state.go b/pkg/common/task/state/state.go index 37bfe9e2..794f9def 100644 --- a/pkg/common/task/state/state.go +++ b/pkg/common/task/state/state.go @@ -8,7 +8,7 @@ import ( "time" "github.com/LumeraProtocol/supernode/pkg/errors" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" "github.com/LumeraProtocol/supernode/pkg/storage/queries" "github.com/LumeraProtocol/supernode/pkg/types" ) @@ -94,18 +94,18 @@ func (state *state) UpdateStatus(subStatus SubStatus) { if state.historyDBStore != nil { if _, err := state.historyDBStore.InsertTaskHistory(history); err != nil { - log.WithError(err).Error("unable to store task status") + logtrace.Error(context.Background(), "unable to store task status", logtrace.Fields{logtrace.FieldError: err.Error()}) } } else { store, err := queries.OpenHistoryDB() if err != nil { - log.WithError(err).Debug("error opening history db") + logtrace.Error(context.Background(), "error opening history db", logtrace.Fields{logtrace.FieldError: err.Error()}) } if store != nil { defer store.CloseHistoryDB(context.Background()) if _, err := store.InsertTaskHistory(history); err != nil { - log.WithError(err).Debug("unable to store task status") + logtrace.Error(context.Background(), "unable to store task status", logtrace.Fields{logtrace.FieldError: err.Error()}) } } } @@ -155,7 +155,7 @@ func (state *state) InitialiseHistoryDB(storeInterface queries.LocalStoreInterfa func New(subStatus SubStatus, taskID string) State { store, err := queries.OpenHistoryDB() if err != nil { - log.WithError(err).Error("error opening history db") + logtrace.Error(context.Background(), "error opening history db", logtrace.Fields{logtrace.FieldError: err.Error()}) } if store != nil { @@ -163,7 +163,7 @@ func New(subStatus SubStatus, taskID string) State { if _, err := store.InsertTaskHistory(types.TaskHistory{CreatedAt: time.Now().UTC(), TaskID: taskID, Status: subStatus.String()}); err != nil { - log.WithError(err).Error("unable to store task status") + logtrace.Error(context.Background(), "unable to store task status", logtrace.Fields{logtrace.FieldError: err.Error()}) } } diff --git a/pkg/common/task/task.go b/pkg/common/task/task.go index 88a64add..bf46e44b 100644 --- a/pkg/common/task/task.go +++ b/pkg/common/task/task.go @@ -9,7 +9,7 @@ import ( "github.com/LumeraProtocol/supernode/pkg/common/task/state" "github.com/LumeraProtocol/supernode/pkg/errgroup" "github.com/LumeraProtocol/supernode/pkg/errors" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" "github.com/LumeraProtocol/supernode/pkg/random" ) @@ -71,7 +71,7 @@ func (task *task) Cancel() { select { case <-task.Done(): - log.Debugf("task %s cancelled", task.ID()) + logtrace.Debug(context.Background(), "task cancelled", logtrace.Fields{"task_id": task.ID()}) return default: close(task.doneCh) @@ -92,13 +92,13 @@ func (task *task) RunAction(ctx context.Context) error { for { select { case <-ctx.Done(): - log.WithContext(ctx).WithField("task", task.ID()).Info("context done") + logtrace.Info(ctx, "context done", logtrace.Fields{"task_id": task.ID()}) case <-task.Done(): - log.WithContext(ctx).Infof("task %s done", task.ID()) + logtrace.Info(ctx, "task done", logtrace.Fields{"task_id": task.ID()}) cancel() case action, ok := <-task.actionCh: if !ok { - log.WithContext(ctx).Info("action channel closed") + logtrace.Info(ctx, "action channel closed", logtrace.Fields{"task_id": task.ID()}) return group.Wait() } diff --git a/pkg/common/task/worker.go b/pkg/common/task/worker.go index 724d74c5..d13ef151 100644 --- a/pkg/common/task/worker.go +++ b/pkg/common/task/worker.go @@ -5,7 +5,7 @@ import ( "sync" "github.com/LumeraProtocol/supernode/pkg/errgroup" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" ) // Worker represents a pool of the task. @@ -62,17 +62,18 @@ func (worker *Worker) Run(ctx context.Context) error { for { select { case <-ctx.Done(): - log.WithContext(ctx).Warn("worker run stopping : %w", ctx.Err()) + logtrace.Warn(ctx, "Worker run stopping", logtrace.Fields{logtrace.FieldError: ctx.Err().Error()}) return group.Wait() case t := <-worker.taskCh: // Rename here currentTask := t // Capture the loop variable group.Go(func() error { defer func() { if r := recover(); r != nil { - log.WithContext(ctx).Errorf("Recovered from panic in common task's worker run: %v", r) + logtrace.Error(ctx, "Recovered from panic in common task's worker run", logtrace.Fields{"task": currentTask.ID(), "error": r}) } - log.WithContext(ctx).WithField("task", currentTask.ID()).Info("Task Removed") + logtrace.Info(ctx, "Task Removed", logtrace.Fields{"task": currentTask.ID()}) + // Remove the task from the worker's task list worker.RemoveTask(currentTask) }() diff --git a/pkg/dd/client.go b/pkg/dd/client.go index 542d1a11..8ffe4e57 100644 --- a/pkg/dd/client.go +++ b/pkg/dd/client.go @@ -5,7 +5,7 @@ import ( "time" "github.com/LumeraProtocol/supernode/pkg/errors" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" "github.com/LumeraProtocol/supernode/pkg/random" "google.golang.org/grpc" "google.golang.org/grpc/encoding/gzip" @@ -35,12 +35,12 @@ func (cl *client) Connect(ctx context.Context, address string) (Connection, erro return nil, errors.Errorf("fail to dial: %w", err).WithField("address", address) } - log.DD().WithContext(ctx).Debugf("Connected to %s with max recv size 35 MB", address) + logtrace.Debug(ctx, "Connected to address with max recv size 35 MB", logtrace.Fields{logtrace.FieldModule: "dd", "address": address}) conn := newClientConn(id, grpcConn) go func() { //<-conn.Done() // FIXME: to be implemented by new gRPC package - log.DD().WithContext(ctx).Debugf("Disconnected %s", grpcConn.Target()) + logtrace.Debug(ctx, "Disconnected", logtrace.Fields{logtrace.FieldModule: "dd", "target": grpcConn.Target()}) }() return conn, nil } diff --git a/pkg/log/context.go b/pkg/log/context.go deleted file mode 100644 index 175ea0bd..00000000 --- a/pkg/log/context.go +++ /dev/null @@ -1,73 +0,0 @@ -package log - -import ( - "context" - - "github.com/LumeraProtocol/supernode/pkg/log/hooks" -) - -type ( - // private type used to define context keys - ctxKey int - serverKey string - taskID string -) - -var ( - ip = "" -) - -const ( - // PrefixKey is the prefix of the log record - PrefixKey ctxKey = iota - // ServerKey is prefix of server ip - ServerKey serverKey = "server" - // TaskIDKey is prefix of task id - TaskIDKey taskID = "task_id" -) - -// ContextWithPrefix returns a new context with PrefixKey value. -func ContextWithPrefix(ctx context.Context, prefix string) context.Context { - - ctx = ContextWithServer(ctx, ip) - - return context.WithValue(ctx, PrefixKey, prefix) -} - -// ContextWithServer returns a new context with ServerKey value. -func ContextWithServer(ctx context.Context, server string) context.Context { - return context.WithValue(ctx, ServerKey, server) -} - -func init() { - AddHook(hooks.NewContextHook(PrefixKey, func(ctxValue interface{}, msg string, fields hooks.ContextHookFields) (string, hooks.ContextHookFields) { - fields["prefix"] = ctxValue - return msg, fields - })) -} - -// GetExternalIPAddress returns external IP address -func GetExternalIPAddress() (externalIP string, err error) { - return "localhost", nil - /*if ip != "" { - return ip, nil - } - - resp, err := http.Get("https://api.ipify.org") - if err != nil { - return "", err - } - - defer resp.Body.Close() - - body, err := io.ReadAll(resp.Body) - if err != nil { - return "", err - } - - if net.ParseIP(string(body)) == nil { - return "", errors.Errorf("invalid IP response from %s", "ipconf.ip") - } - - return string(body), nil*/ -} diff --git a/pkg/log/debug.go b/pkg/log/debug.go deleted file mode 100644 index ac83a233..00000000 --- a/pkg/log/debug.go +++ /dev/null @@ -1,46 +0,0 @@ -package log - -import ( - "fmt" - "os" - "path/filepath" - "runtime" - "strings" - - "github.com/LumeraProtocol/supernode/pkg/utils" -) - -var ( - runDir string - - // if `debugMode` is true, log record will contain `file` field, with a value that indicating where the log was called. - debugMode bool -) - -// SetDebugMode sets the state of debug mode -func SetDebugMode(isEnabled bool) { - debugMode = isEnabled -} - -// DebugMode returns the state of debug mode -func DebugMode() bool { - return debugMode -} - -func fileInfo(skip int) string { - _, file, line, ok := runtime.Caller(skip) - if !ok { - file = "" - line = 1 - } else { - commonPath := utils.Prefix([]string{runDir, file}) - commonDir := filepath.Dir(commonPath) - - file = strings.TrimPrefix(file, strings.TrimSuffix(commonDir, "/")) - } - return fmt.Sprintf("%s:%d", file, line) -} - -func init() { - runDir, _ = os.Getwd() -} diff --git a/pkg/log/entry.go b/pkg/log/entry.go deleted file mode 100644 index 513032f3..00000000 --- a/pkg/log/entry.go +++ /dev/null @@ -1,238 +0,0 @@ -package log - -import ( - "context" - "time" - - "github.com/LumeraProtocol/supernode/pkg/errors" - "github.com/LumeraProtocol/supernode/pkg/log/hooks" - "github.com/sirupsen/logrus" -) - -const ( - defaultSkipCallers = 4 -) - -// Fields type, used to pass to `WithFields`. -type Fields logrus.Fields - -// Entry represents a wrapped logrus.Entry -type Entry struct { - *logrus.Entry - level logrus.Level -} - -// WithField adds a single field to the Entry. -func (entry *Entry) WithField(key string, value interface{}) *Entry { - return &Entry{Entry: entry.Entry.WithField(key, value), level: entry.level} -} - -// WithFields adds a map of fields to the Entry. -func (entry *Entry) WithFields(fields Fields) *Entry { - return &Entry{Entry: entry.Entry.WithFields(logrus.Fields(fields)), level: entry.level} -} - -// WithErrorStack adds an field `error` and `stack` to the Entry. -func (entry *Entry) WithErrorStack(err error) *Entry { - return entry.WithError(err).WithField("stack", errors.ErrorStack(err)) -} - -// WithError adds an field `error` to the Entry. -func (entry *Entry) WithError(err error) *Entry { - fields := errors.ExtractFields(err) - return &Entry{Entry: entry.Entry.WithError(err).WithFields(map[string]interface{}(fields)), level: entry.level} -} - -// WithContext adds a context to the Entry. -func (entry *Entry) WithContext(ctx context.Context) *Entry { - ent := &Entry{Entry: entry.Entry.WithContext(ctx), level: entry.level} - server := ctx.Value(ServerKey) - return ent.WithField("server_ip", server) -} - -// WithDuration adds an field `duration` with value of the time elapsed since t. -func (entry *Entry) WithDuration(t time.Time) *Entry { - return &Entry{Entry: entry.Entry.WithField(hooks.DurationFieldName, t), level: entry.level} -} - -// WithPrefix adds a prefix as single field (using the key `prefix`) to the Entry. -func (entry *Entry) WithPrefix(value string) *Entry { - return &Entry{Entry: entry.Entry.WithField("prefix", value), level: entry.level} -} - -// Trace logs a message at level Trace. -func (entry *Entry) Trace(args ...interface{}) { - if entry.level >= logrus.TraceLevel { - entry.Entry.Trace(args...) - } -} - -// Debug logs a message at level Debug. -func (entry *Entry) Debug(args ...interface{}) { - if entry.level >= logrus.DebugLevel { - entry.Entry.Debug(args...) - } -} - -// Print logs a message at level Print. -func (entry *Entry) Print(args ...interface{}) { - entry.Entry.Print(args...) -} - -// Info logs a message at level Info. -func (entry *Entry) Info(args ...interface{}) { - if entry.level >= logrus.InfoLevel { - entry.Entry.Info(args...) - } -} - -// Warn logs a message at level Warn. -func (entry *Entry) Warn(args ...interface{}) { - if entry.level >= logrus.WarnLevel { - entry.Entry.Warn(args...) - } -} - -// Error logs a message at level Error. -func (entry *Entry) Error(args ...interface{}) { - if entry.level >= logrus.ErrorLevel { - entry.Entry.Error(args...) - } -} - -// Fatal logs a message at level Fatal. -func (entry *Entry) Fatal(args ...interface{}) { - if entry.level >= logrus.FatalLevel { - entry.Entry.Log(logrus.FatalLevel, args...) - } -} - -// Entry Printf family functions - -// Tracef logs a message at level Trace. -func (entry *Entry) Tracef(format string, args ...interface{}) { - if entry.level >= logrus.TraceLevel { - entry.Entry.Tracef(format, args...) - } -} - -// Debugf logs a message at level Debug. -func (entry *Entry) Debugf(format string, args ...interface{}) { - if entry.level >= logrus.DebugLevel { - entry.Entry.Debugf(format, args...) - } -} - -// Infof logs a message at level Info. -func (entry *Entry) Infof(format string, args ...interface{}) { - if entry.level >= logrus.InfoLevel { - entry.Entry.Infof(format, args...) - } -} - -// Printf logs a message at level Print. -func (entry *Entry) Printf(format string, args ...interface{}) { - entry.Entry.Printf(format, args...) -} - -// Warnf logs a message at level Warn. -func (entry *Entry) Warnf(format string, args ...interface{}) { - if entry.level >= logrus.WarnLevel { - entry.Entry.Warnf(format, args...) - } -} - -// Errorf logs a message at level Error. -func (entry *Entry) Errorf(format string, args ...interface{}) { - if entry.level >= logrus.ErrorLevel { - entry.Entry.Errorf(format, args...) - } -} - -// Fatalf logs a message at level Fatal. -func (entry *Entry) Fatalf(format string, args ...interface{}) { - if entry.level >= logrus.FatalLevel { - entry.Entry.Fatalf(format, args...) - } -} - -// Logf logs a message at the provided level -func (entry *Entry) Logf(levelName, format string, args ...interface{}) { - level, err := logrus.ParseLevel(levelName) - if err != nil { - level = logrus.InfoLevel - } - if entry.level >= level { - entry.Entry.Logf(level, format, args...) - } -} - -// Entry Println family functions - -// Traceln logs a message at level Trace. -func (entry *Entry) Traceln(args ...interface{}) { - if entry.level >= logrus.TraceLevel { - entry.Entry.Traceln(args...) - } -} - -// Debugln logs a message at level Debug. -func (entry *Entry) Debugln(args ...interface{}) { - if entry.level >= logrus.DebugLevel { - entry.Entry.Debugln(args...) - } -} - -// Infoln logs a message at level Info. -func (entry *Entry) Infoln(args ...interface{}) { - if entry.level >= logrus.InfoLevel { - entry.Entry.Infoln(args...) - } -} - -// Println logs a message at level Print. -func (entry *Entry) Println(args ...interface{}) { - entry.Entry.Println(args...) -} - -// Warnln logs a message at level Warn. -func (entry *Entry) Warnln(args ...interface{}) { - if entry.level >= logrus.WarnLevel { - entry.Entry.Warnln(args...) - } -} - -// Errorln logs a message at level Error. -func (entry *Entry) Errorln(args ...interface{}) { - if entry.level >= logrus.ErrorLevel { - entry.Entry.Errorln(args...) - } -} - -// Fatalln logs a message at level Fatal. -func (entry *Entry) Fatalln(args ...interface{}) { - if entry.level >= logrus.FatalLevel { - entry.Entry.Fatalln(args...) - } -} - -// WithCaller adds caller field to the Entry. -func (entry *Entry) WithCaller(skip int) *Entry { - if debugMode { - entry.Data["file"] = fileInfo(skip) - } - return entry -} - -// NewEntry returns a new Entry instance. -func NewEntry(logger *Logger, level logrus.Level) *Entry { - return (&Entry{ - Entry: logrus.NewEntry(logger.Logger), - level: level, - }) -} - -// NewDefaultEntry returns a new Entry instance using default logger. -func NewDefaultEntry() *Entry { - return NewEntry(DefaultLogger, currentDefaultLevel).WithCaller(defaultSkipCallers) -} diff --git a/pkg/log/exported.go b/pkg/log/exported.go deleted file mode 100644 index 48dbdf9e..00000000 --- a/pkg/log/exported.go +++ /dev/null @@ -1,174 +0,0 @@ -package log - -import ( - "context" - "fmt" - "os" - "time" - - "github.com/LumeraProtocol/supernode/pkg/errors" - "github.com/LumeraProtocol/supernode/pkg/log/hooks" -) - -// WithError adds an error to log entry. -func WithError(err error) *Entry { - return NewDefaultEntry().WithError(err) -} - -// WithErrorStack adds an `error` and `stack` to log Entry. -func WithErrorStack(err error) *Entry { - return NewDefaultEntry().WithErrorStack(err) -} - -// WithPrefix adds a prefix to log entry. -func WithPrefix(value string) *Entry { - return NewDefaultEntry().WithField("prefix", value) -} - -// WithContext adds an context to log entry, using the value defined inside of context. -func WithContext(ctx context.Context) *Entry { - return NewDefaultEntry().WithContext(ctx) -} - -// WithDuration adds an field `duration` with value of the time elapsed since t. -func WithDuration(t time.Time) *Entry { - return NewDefaultEntry().WithField(hooks.DurationFieldName, t) -} - -// WithField adds a field to entry. -func WithField(key string, value interface{}) *Entry { - return NewDefaultEntry().WithField(key, value) -} - -// WithFields adds multiple fields to entry. -func WithFields(fields Fields) *Entry { - return NewDefaultEntry().WithFields(fields) -} - -// Debug logs a message at level Debug. -func Debug(args ...interface{}) { - NewDefaultEntry().Debug(args...) -} - -// Info logs a message at level Info. -func Info(args ...interface{}) { - NewDefaultEntry().Info(args...) -} - -// Print logs a message at level Info. -func Print(args ...interface{}) { - NewDefaultEntry().Print(args...) -} - -// Warn logs a message at level Warn. -func Warn(args ...interface{}) { - NewDefaultEntry().Warn(args...) -} - -// Error logs a message at level Error. -func Error(args ...interface{}) { - NewDefaultEntry().Error(args...) -} - -// Debugln logs a message at level Debug. -func Debugln(args ...interface{}) { - NewDefaultEntry().Debugln(args...) -} - -// Infoln logs a message at level Info. -func Infoln(args ...interface{}) { - NewDefaultEntry().Infoln(args...) -} - -// Println logs a message at level Info. -func Println(args ...interface{}) { - NewDefaultEntry().Println(args...) -} - -// Warnln logs a message at level Warn. -func Warnln(args ...interface{}) { - NewDefaultEntry().Warnln(args...) -} - -// Errorln logs a message at level Error. -func Errorln(args ...interface{}) { - NewDefaultEntry().Errorln(args...) -} - -// Debugf logs a message at level Debug. -func Debugf(format string, args ...interface{}) { - NewDefaultEntry().Debugf(format, args...) -} - -// Infof logs a message at level Info. -func Infof(format string, args ...interface{}) { - NewDefaultEntry().Infof(format, args...) -} - -// Printf logs a message at level Info. -func Printf(args ...interface{}) { - NewDefaultEntry().Print(args...) -} - -// Warnf logs a message at level Warn. -func Warnf(format string, args ...interface{}) { - NewDefaultEntry().Warnf(format, args...) -} - -// Errorf logs a message at level Error. -func Errorf(format string, args ...interface{}) { - NewDefaultEntry().Errorf(format, args...) -} - -// Tracef logs a message at level Trace. -func Tracef(format string, args ...interface{}) { - NewDefaultEntry().Tracef(format, args...) -} - -// Logf logs a message at the provided level -func Logf(levelName, format string, args ...interface{}) { - NewDefaultEntry().Logf(levelName, format, args...) -} - -// Fatal logs an error at level Fatal with error stack. -func Fatal(err error) { - entry := NewDefaultEntry() - if debugMode { - entry = entry.WithErrorStack(err) - } - entry.Fatal(err) -} - -// FatalAndExit checks if there is an error, display it in the console and exit with a non-zero exit code. Otherwise, exit 0. -// Note that if the debugMode is true, this will print out the stack trace. -func FatalAndExit(err error) { - if err == nil || errors.IsContextCanceled(err) { - return - } - defer os.Exit(errors.ExitCode(err)) - - Fatal(err) - - fmt.Fprintf(os.Stderr, "ERROR: %s\n", err) -} - -// WithSub return a log entry - with log level of given sub domain - using SetSubLevelName() to set sub level -// but even with specific default level, but sub domain logs are also filtered by DefaultLogger's log level -func WithSub(subName string) *Entry { - return NewEntry(DefaultLogger, getSubLogLevel(subName)) -} - -// P2P return a log entry - of p2p subsystem -func P2P() *Entry { - return NewEntry(DefaultLogger, getSubLogLevel(p2pSubName)) -} - -// MetaDB return a log entry - of metadb subsystem -func MetaDB() *Entry { - return NewEntry(DefaultLogger, getSubLogLevel(metadbSubName)) -} - -// DD return a log entry of dupe detection subsystem -func DD() *Entry { - return NewEntry(DefaultLogger, getSubLogLevel(ddSubName)) -} diff --git a/pkg/log/formatters/text_formatter.go b/pkg/log/formatters/text_formatter.go deleted file mode 100644 index 397b67b1..00000000 --- a/pkg/log/formatters/text_formatter.go +++ /dev/null @@ -1,43 +0,0 @@ -package formatters - -import ( - "github.com/sirupsen/logrus" - prefixed "github.com/x-cray/logrus-prefixed-formatter" -) - -// Global formatters -var ( - LogFile = NewFileFormatter() - Terminal = NewTerminalFormatter() -) - -// NewFileFormatter returns a new Formatter instance for log file. -func NewFileFormatter() logrus.Formatter { - return &prefixed.TextFormatter{ - FullTimestamp: true, - TimestampFormat: "Jan 02 15:04:05.000", - DisableColors: true, - ForceFormatting: true, - } -} - -// NewTerminalFormatter returns a new Formatter instance for terminal. -func NewTerminalFormatter() logrus.Formatter { - formatter := &prefixed.TextFormatter{ - FullTimestamp: true, - TimestampFormat: "Jan 02 15:04:05.000", - ForceFormatting: true, - } - formatter.SetColorScheme(&prefixed.ColorScheme{ - InfoLevelStyle: "green", - WarnLevelStyle: "yellow", - ErrorLevelStyle: "red", - FatalLevelStyle: "red", - PanicLevelStyle: "red", - DebugLevelStyle: "blue+h", - PrefixStyle: "cyan", - TimestampStyle: "black+h", - }) - - return formatter -} diff --git a/pkg/log/hooks/context.go b/pkg/log/hooks/context.go deleted file mode 100644 index e3081a2a..00000000 --- a/pkg/log/hooks/context.go +++ /dev/null @@ -1,46 +0,0 @@ -package hooks - -import ( - "github.com/sirupsen/logrus" -) - -// ContextHookFields is log fields -type ContextHookFields map[string]interface{} - -// ContextHookFn is the callback function for formating message -type ContextHookFn func(ctxValue interface{}, msg string, fields ContextHookFields) (string, ContextHookFields) - -// ContextHook represents a hook for logrus logger. -type ContextHook struct { - contextKey interface{} - fn ContextHookFn -} - -// Fire implements logrus.ContextHook.Fire() -func (hook *ContextHook) Fire(entry *logrus.Entry) error { - if entry.Context == nil { - return nil - } - - ctxValue := entry.Context.Value(hook.contextKey) - if ctxValue != nil { - msg, fields := hook.fn(ctxValue, entry.Message, ContextHookFields(entry.Data)) - - entry.Message = msg - entry.Data = logrus.Fields(fields) - } - return nil -} - -// Levels implements logrus.ContextHook.Levels() -func (hook *ContextHook) Levels() []logrus.Level { - return logrus.AllLevels -} - -// NewContextHook creates a new ContextHook instance -func NewContextHook(contextKey interface{}, fn ContextHookFn) *ContextHook { - return &ContextHook{ - contextKey: contextKey, - fn: fn, - } -} diff --git a/pkg/log/hooks/duration.go b/pkg/log/hooks/duration.go deleted file mode 100644 index 3ef9becc..00000000 --- a/pkg/log/hooks/duration.go +++ /dev/null @@ -1,42 +0,0 @@ -package hooks - -import ( - "time" - - "github.com/sirupsen/logrus" -) - -const ( - // DurationFieldName is field key. - DurationFieldName = "duration" -) - -// DurationHook represents a hook for logrus logger. -type DurationHook struct{} - -// Fire implements logrus.DurationHook.Fire() -func (hook *DurationHook) Fire(entry *logrus.Entry) error { - field, ok := entry.Data[DurationFieldName] - if !ok { - return nil - } - - start, ok := field.(time.Time) - if !ok { - return nil - } - delete(entry.Data, DurationFieldName) - entry.Data[DurationFieldName] = time.Since(start).String() - - return nil -} - -// Levels implements logrus.DurationHook.Levels() -func (hook *DurationHook) Levels() []logrus.Level { - return logrus.AllLevels -} - -// NewDurationHook creates a new DurationHook instance -func NewDurationHook() *DurationHook { - return &DurationHook{} -} diff --git a/pkg/log/hooks/file.go b/pkg/log/hooks/file.go deleted file mode 100644 index 0e8ba466..00000000 --- a/pkg/log/hooks/file.go +++ /dev/null @@ -1,96 +0,0 @@ -package hooks - -import ( - "fmt" - "math" - "time" - - "github.com/LumeraProtocol/supernode/pkg/log/formatters" - "github.com/sirupsen/logrus" - "gopkg.in/natefinch/lumberjack.v2" -) - -var ( - defaultFormatter = formatters.LogFile - defaultMaxSize = 104857600 // 100Mb - defaultMaxAge = time.Second * 86400 - defaultCompress = false -) - -// FileHook is a hook to handle writing to queries log files. -type FileHook struct { - fileLogger *lumberjack.Logger - formatter logrus.Formatter -} - -// SetFormatter sets the format that will be used by hook. -func (hook *FileHook) SetFormatter(formatter logrus.Formatter) { - hook.formatter = formatter -} - -// SetMaxAge sets the maximum duration to retain old log files based on the timestamp encoded in their filename. -func (hook *FileHook) SetMaxAge(maxAge time.Duration) { - days, _ := math.Modf(maxAge.Hours() / 24) - hook.fileLogger.MaxAge = int(days) -} - -// SetMaxAgeInDays sets the maximum duration(in days) to retain old log files based on the timestamp encoded in their filename. -func (hook *FileHook) SetMaxAgeInDays(maxAgeInDays int) { - hook.fileLogger.MaxAge = maxAgeInDays -} - -// SetMaxSize sets the maximum size in megabytes of the log file before it gets rotated. -func (hook *FileHook) SetMaxSize(maxSize int) { - size := maxSize / 1048576 // to Megabytes - hook.fileLogger.MaxSize = size -} - -// SetMaxSizeInMB sets the maximum size in megabytes of the log file before it gets rotated. -func (hook *FileHook) SetMaxSizeInMB(maxSizeInMB int) { - hook.fileLogger.MaxSize = maxSizeInMB -} - -// SetMaxBackups set the maximum number of old log files to retain. The default -// is to retain all old log files (though MaxAge may still cause them to get -// deleted.) -func (hook *FileHook) SetMaxBackups(maxBackups int) { - hook.fileLogger.MaxBackups = maxBackups -} - -// SetCompress determines if the rotated log files should be compressed -// using gzip. The default is not to perform compression. -func (hook *FileHook) SetCompress(compress bool) { - hook.fileLogger.Compress = compress -} - -// Fire writes the log file to defined filename path. -func (hook *FileHook) Fire(entry *logrus.Entry) error { - msg, err := hook.formatter.Format(entry) - if err != nil { - return fmt.Errorf("generate string for entry: %s", err) - } - - _, err = hook.fileLogger.Write(msg) - return err -} - -// Levels returns configured log levels. -func (hook *FileHook) Levels() []logrus.Level { - return logrus.AllLevels -} - -// NewFileHook returns new FileHook instance with default values. -func NewFileHook(filename string) *FileHook { - hook := &FileHook{ - fileLogger: &lumberjack.Logger{ - Filename: filename, - Compress: defaultCompress, - }, - } - - hook.SetFormatter(defaultFormatter) - hook.SetMaxAge(defaultMaxAge) - hook.SetMaxSize(defaultMaxSize) - - return hook -} diff --git a/pkg/log/log.go b/pkg/log/log.go deleted file mode 100644 index 6225d2a9..00000000 --- a/pkg/log/log.go +++ /dev/null @@ -1,81 +0,0 @@ -package log - -import ( - "io" - "sync" - - "github.com/sirupsen/logrus" -) - -const ( - metadbSubName = "metadb" - p2pSubName = "p2p" - ddSubName = "dd" -) - -// DefaultLogger is logger with default settings -var DefaultLogger = NewLogger() -var subLevels = map[string]logrus.Level{} -var currentDefaultLevel = logrus.InfoLevel -var mtx = sync.RWMutex{} - -// SetLevelName parses and sets the defaultLogger level. -func SetLevelName(name string) error { - level, err := logrus.ParseLevel(name) - if err != nil { - return err - } - - currentDefaultLevel = level - - return nil -} - -// SetOutput sets the defaultLogger output. -func SetOutput(output io.Writer) { - DefaultLogger.SetOutput(output) -} - -// SetSubLevelName parses and sets the level for a subsystem with given name. -func SetSubLevelName(subName string, levelName string) error { - level, err := logrus.ParseLevel(levelName) - if err != nil { - return err - } - mtx.Lock() - defer mtx.Unlock() - subLevels[subName] = level - return nil -} - -// SetP2PLogLevelName sets log level of p2p subsystem -func SetP2PLogLevelName(levelName string) error { - return SetSubLevelName(p2pSubName, levelName) -} - -// SetMetaDBLogLevelName sets log level of metadb subsystem -func SetMetaDBLogLevelName(levelName string) error { - return SetSubLevelName(metadbSubName, levelName) -} - -// SetDDLogLevelName sets log level of dupe subsystem -func SetDDLogLevelName(levelName string) error { - return SetSubLevelName(ddSubName, levelName) -} - -func getSubLogLevel(subName string) logrus.Level { - mtx.RLock() - defer mtx.RUnlock() - level, ok := subLevels[subName] - if !ok { - // default level - return currentDefaultLevel - } - - return level -} - -// AddHook adds hook to an instance of defaultLogger. -func AddHook(hook logrus.Hook) { - DefaultLogger.Hooks.Add(hook) -} diff --git a/pkg/log/logger.go b/pkg/log/logger.go deleted file mode 100644 index 3c7a84af..00000000 --- a/pkg/log/logger.go +++ /dev/null @@ -1,54 +0,0 @@ -package log - -import ( - "github.com/LumeraProtocol/supernode/pkg/log/formatters" - "github.com/sirupsen/logrus" -) - -const ( - defaultLevel = logrus.InfoLevel -) - -// Logger represents a wrapped logrus.Logger -type Logger struct { - *logrus.Logger -} - -// NewLogger returns a new Logger instance with default values -func NewLogger() *Logger { - logger := logrus.New() - logger.SetFormatter(formatters.Terminal) - logger.SetLevel(defaultLevel) - - return &Logger{ - Logger: logger, - } -} - -// NewLoggerWithErrorLevel returns a new Logger instance with default values -func NewLoggerWithErrorLevel() *Logger { - logger := logrus.New() - logger.SetFormatter(formatters.Terminal) - logger.SetLevel(logrus.ErrorLevel) - - return &Logger{ - Logger: logger, - } -} - -// V sets verbose level -func (l *Logger) V(level int) bool { - switch level { - case 0: - return true // always log errors - case 1: - return true // always log warnings - case 2: - return false // always log info - case 3: - return false // never log debug - default: - return false - } - -} diff --git a/pkg/log/logger_test.go b/pkg/log/logger_test.go deleted file mode 100644 index ace10159..00000000 --- a/pkg/log/logger_test.go +++ /dev/null @@ -1,18 +0,0 @@ -package log - -import ( - "testing" -) - -// TestLoggers is sample app -func TestLoggers(_ *testing.T) { - WithSub("hello").WithField("core", "value").Warn("Warn1") - WithSub("hello").WithField("core", "value").Info("Info1") - WithSub("hello").WithField("core", "value").Error("Error1") - SetSubLevelName("hello", "error") - SetLevelName("error") - WithSub("hello").WithField("core", "value").Warn("Warn2") - WithSub("hello").WithField("core", "value").Info("Info2") - WithSub("hello").WithField("core", "value").Error("Error2") - WithField("core", "value").Error("default logging") -} diff --git a/pkg/logtrace/.gitkeep b/pkg/logtrace/.gitkeep deleted file mode 100644 index e69de29b..00000000 diff --git a/pkg/logtrace/grpc_logger.go b/pkg/logtrace/grpc_logger.go new file mode 100644 index 00000000..5d444b5f --- /dev/null +++ b/pkg/logtrace/grpc_logger.go @@ -0,0 +1,92 @@ +package logtrace + +import ( + "context" + "fmt" + + "google.golang.org/grpc/grpclog" +) + +// grpcLogger implements grpclog.LoggerV2 interface using logtrace +type grpcLogger struct { + ctx context.Context +} + +// NewGRPCLogger creates a new gRPC-compatible logger using logtrace +func NewGRPCLogger(ctx context.Context) grpclog.LoggerV2 { + return &grpcLogger{ctx: ctx} +} + +// Info logs at info level +func (g *grpcLogger) Info(args ...interface{}) { + Info(g.ctx, fmt.Sprint(args...), Fields{FieldModule: "grpc"}) +} + +// Infof logs at info level with format +func (g *grpcLogger) Infof(format string, args ...interface{}) { + Info(g.ctx, fmt.Sprintf(format, args...), Fields{FieldModule: "grpc"}) +} + +// Infoln logs at info level with newline +func (g *grpcLogger) Infoln(args ...interface{}) { + g.Info(args...) +} + +// Warning logs at warn level +func (g *grpcLogger) Warning(args ...interface{}) { + Warn(g.ctx, fmt.Sprint(args...), Fields{FieldModule: "grpc"}) +} + +// Warningf logs at warn level with format +func (g *grpcLogger) Warningf(format string, args ...interface{}) { + Warn(g.ctx, fmt.Sprintf(format, args...), Fields{FieldModule: "grpc"}) +} + +// Warningln logs at warn level with newline +func (g *grpcLogger) Warningln(args ...interface{}) { + g.Warning(args...) +} + +// Error logs at error level +func (g *grpcLogger) Error(args ...interface{}) { + Error(g.ctx, fmt.Sprint(args...), Fields{FieldModule: "grpc"}) +} + +// Errorf logs at error level with format +func (g *grpcLogger) Errorf(format string, args ...interface{}) { + Error(g.ctx, fmt.Sprintf(format, args...), Fields{FieldModule: "grpc"}) +} + +// Errorln logs at error level with newline +func (g *grpcLogger) Errorln(args ...interface{}) { + g.Error(args...) +} + +// Fatal logs at error level and panics +func (g *grpcLogger) Fatal(args ...interface{}) { + msg := fmt.Sprint(args...) + Error(g.ctx, msg, Fields{FieldModule: "grpc", "level": "fatal"}) + panic(msg) +} + +// Fatalf logs at error level with format and panics +func (g *grpcLogger) Fatalf(format string, args ...interface{}) { + msg := fmt.Sprintf(format, args...) + Error(g.ctx, msg, Fields{FieldModule: "grpc", "level": "fatal"}) + panic(msg) +} + +// Fatalln logs at error level with newline and panics +func (g *grpcLogger) Fatalln(args ...interface{}) { + g.Fatal(args...) +} + +// V returns true if logging is enabled for the given verbosity level +func (g *grpcLogger) V(l int) bool { + return l <= 1 // Only show error/warning levels by default +} + +// SetGRPCLogger configures gRPC to use logtrace for internal logging +func SetGRPCLogger(ctx context.Context) { + grpclog.SetLoggerV2(NewGRPCLogger(ctx)) +} diff --git a/pkg/logtrace/log.go b/pkg/logtrace/log.go index bd6845b5..a6db8bb3 100644 --- a/pkg/logtrace/log.go +++ b/pkg/logtrace/log.go @@ -4,6 +4,7 @@ import ( "context" "fmt" "log/slog" + "maps" "os" "runtime" ) @@ -62,10 +63,8 @@ func extractCorrelationID(ctx context.Context) string { // addCorrelationID ensures logs include the correlation ID without modifying the input fields. func addCorrelationID(ctx context.Context, fields Fields) Fields { newFields := make(Fields, len(fields)+1) // Copy fields to avoid mutation - for k, v := range fields { - newFields[k] = v - } - newFields["correlation_id"] = extractCorrelationID(ctx) + maps.Copy(newFields, fields) + newFields[FieldCorrelationID] = extractCorrelationID(ctx) return newFields } @@ -84,7 +83,12 @@ func Warn(ctx context.Context, message string, fields Fields) { log(slog.Warn, message, addCorrelationID(ctx, fields)) } -// CtxWithCorrelationID stores a correlation ID inside the gRPC context. +// Debug logs a debug message with structured fields. +func Debug(ctx context.Context, message string, fields Fields) { + log(slog.Debug, message, addCorrelationID(ctx, fields)) +} + +// CtxWithCorrelationID stores a correlation ID inside the context. func CtxWithCorrelationID(ctx context.Context, correlationID string) context.Context { return context.WithValue(ctx, CorrelationIDKey, correlationID) } diff --git a/pkg/net/credentials/lumeratc.go b/pkg/net/credentials/lumeratc.go index 47ee57f7..dc796683 100644 --- a/pkg/net/credentials/lumeratc.go +++ b/pkg/net/credentials/lumeratc.go @@ -1,19 +1,19 @@ package credentials import ( - "fmt" "context" + "crypto/ecdh" + "fmt" "net" "sync" - "crypto/ecdh" - "google.golang.org/grpc/credentials" "github.com/cosmos/cosmos-sdk/crypto/keyring" + "google.golang.org/grpc/credentials" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/lumera/x/lumeraid/securekeyx" + "github.com/LumeraProtocol/supernode/pkg/logtrace" . "github.com/LumeraProtocol/supernode/pkg/net/credentials/alts/common" "github.com/LumeraProtocol/supernode/pkg/net/credentials/alts/handshake" - "github.com/LumeraProtocol/lumera/x/lumeraid/securekeyx" ) const RemoteIdentityKey = "remoteIdentity" @@ -25,11 +25,11 @@ var ( // CommonOptions contains the shared configuration for both client and server type CommonOptions struct { - Keyring keyring.Keyring - LocalIdentity string // Local Cosmos address - PeerType securekeyx.PeerType // Local peer type - Curve ecdh.Curve - Validator securekeyx.KeyExchangerValidator + Keyring keyring.Keyring + LocalIdentity string // Local Cosmos address + PeerType securekeyx.PeerType // Local peer type + Curve ecdh.Curve + Validator securekeyx.KeyExchangerValidator } // ClientOptions contains client-specific configuration @@ -66,10 +66,10 @@ func DefaultServerOptions() *ServerOptions { // LumeraTC implements the TransportCredentials interface for Lumera secure communication type LumeraTC struct { - info *credentials.ProtocolInfo - side Side - remoteIdentity string - keyExchanger *securekeyx.SecureKeyExchange + info *credentials.ProtocolInfo + side Side + remoteIdentity string + keyExchanger *securekeyx.SecureKeyExchange } // NewTransportCredentials creates a new TransportCredentials with the given options @@ -118,9 +118,9 @@ func NewTransportCredentials(side Side, opts interface{}) (credentials.Transport return &LumeraTC{ info: &credentials.ProtocolInfo{ SecurityProtocol: LumeraALTSProtocol, - SecurityVersion: "1.0", + SecurityVersion: "1.0", }, - side: side, + side: side, keyExchanger: keyExchanger, }, nil } @@ -137,7 +137,7 @@ func NewServerCreds(opts *ServerOptions) (credentials.TransportCredentials, erro // ClientHandshake performs the client-side handshake func (l *LumeraTC) ClientHandshake(ctx context.Context, authority string, rawConn net.Conn) (net.Conn, credentials.AuthInfo, error) { - ctx = log.ContextWithPrefix(ctx, "lumera-handshake") + ctx = logtrace.CtxWithCorrelationID(ctx, "lumera-handshake") opts := handshake.DefaultClientHandshakerOptions() clientHS := handshake.NewClientHandshaker(l.keyExchanger, rawConn, l.remoteIdentity, opts) @@ -151,7 +151,7 @@ func (l *LumeraTC) ClientHandshake(ctx context.Context, authority string, rawCon // ServerHandshake performs the server-side handshake func (l *LumeraTC) ServerHandshake(rawConn net.Conn) (net.Conn, credentials.AuthInfo, error) { - //ctx = log.ContextWithPrefix(ctx, "lumera-handshake") + //ctx = logtrace.CtxWithCorrelationID(ctx, "lumera-handshake") opts := handshake.DefaultServerHandshakerOptions() serverHS := handshake.NewServerHandshaker(l.keyExchanger, rawConn, opts) @@ -169,10 +169,10 @@ func (l *LumeraTC) Info() credentials.ProtocolInfo { func (l *LumeraTC) Clone() credentials.TransportCredentials { return &LumeraTC{ - info: l.info, - side: l.side, + info: l.info, + side: l.side, remoteIdentity: l.remoteIdentity, - keyExchanger: l.keyExchanger, + keyExchanger: l.keyExchanger, } } @@ -193,4 +193,3 @@ type LumeraAuthInfo struct { func (l *LumeraAuthInfo) AuthType() string { return LumeraALTSProtocol } - diff --git a/pkg/net/grpc/client/client.go b/pkg/net/grpc/client/client.go index beaec6a0..be8ffbe7 100644 --- a/pkg/net/grpc/client/client.go +++ b/pkg/net/grpc/client/client.go @@ -9,32 +9,31 @@ import ( "time" "google.golang.org/grpc" + "google.golang.org/grpc/backoff" "google.golang.org/grpc/connectivity" "google.golang.org/grpc/credentials" "google.golang.org/grpc/credentials/insecure" "google.golang.org/grpc/keepalive" - "google.golang.org/grpc/backoff" - "google.golang.org/grpc/grpclog" - "github.com/LumeraProtocol/supernode/pkg/log" - "github.com/LumeraProtocol/supernode/pkg/random" + "github.com/LumeraProtocol/supernode/pkg/logtrace" ltc "github.com/LumeraProtocol/supernode/pkg/net/credentials" + "github.com/LumeraProtocol/supernode/pkg/random" ) const ( - _ = iota + _ = iota KB int = 1 << (10 * iota) // 1024 MB // 1048576 GB // 1073741824 ) const ( - defaultTimeout = 30 * time.Second - defaultConnWaitTime = 10 * time.Second + defaultTimeout = 30 * time.Second + defaultConnWaitTime = 10 * time.Second defaultRetryWaitTime = 1 * time.Second maxRetries = 3 - logPrefix = "client" + logPrefix = "client" ) type grpcClient interface { @@ -67,19 +66,19 @@ type ClientConn interface { // Client represents a gRPC client with Lumera ALTS credentials type Client struct { - creds credentials.TransportCredentials - builder DialOptionBuilder + creds credentials.TransportCredentials + builder DialOptionBuilder connHandler ConnectionHandler } // ClientOptions contains options for creating a new client type ClientOptions struct { // Connection parameters - MaxRecvMsgSize int // Maximum message size the client can receive (in bytes) - MaxSendMsgSize int // Maximum message size the client can send (in bytes) - InitialWindowSize int32 // Initial window size for stream flow control - InitialConnWindowSize int32 // Initial window size for connection flow control - ConnWaitTime time.Duration // Maximum time to wait for connection to become ready + MaxRecvMsgSize int // Maximum message size the client can receive (in bytes) + MaxSendMsgSize int // Maximum message size the client can send (in bytes) + InitialWindowSize int32 // Initial window size for stream flow control + InitialConnWindowSize int32 // Initial window size for connection flow control + ConnWaitTime time.Duration // Maximum time to wait for connection to become ready // Keepalive parameters KeepAliveTime time.Duration // Time after which client pings server if there's no activity @@ -87,12 +86,12 @@ type ClientOptions struct { AllowWithoutStream bool // Allow pings even when there are no active streams // Retry parameters - MaxRetries int // Maximum number of connection retry attempts - RetryWaitTime time.Duration // Time to wait between retry attempts - EnableRetries bool // Whether to enable connection retry logic + MaxRetries int // Maximum number of connection retry attempts + RetryWaitTime time.Duration // Time to wait between retry attempts + EnableRetries bool // Whether to enable connection retry logic // Backoff parameters - controls how retry delays increase over time - BackoffConfig *backoff.Config // Configuration for retry backoff strategy + BackoffConfig *backoff.Config // Configuration for retry backoff strategy // Additional options UserAgent string // User-Agent header value for all requests @@ -104,29 +103,29 @@ type ClientOptions struct { // BaseDelay * (Multiplier ^ n) * (1 ± Jitter) var defaultBackoffConfig = backoff.Config{ BaseDelay: 1.0 * time.Second, // Initial delay between retries - Multiplier: 1.6, // Factor by which the delay increases - Jitter: 0.2, // Randomness factor to prevent thundering herd + Multiplier: 1.6, // Factor by which the delay increases + Jitter: 0.2, // Randomness factor to prevent thundering herd MaxDelay: 120 * time.Second, // Maximum delay between retries } // DefaultClientOptions returns default client options func DefaultClientOptions() *ClientOptions { return &ClientOptions{ - MaxRecvMsgSize: 100 * MB, - MaxSendMsgSize: 100 * MB, // 100MB + MaxRecvMsgSize: 100 * MB, + MaxSendMsgSize: 100 * MB, // 100MB InitialWindowSize: (int32)(1 * MB), // 1MB - controls initial frame size for streams InitialConnWindowSize: (int32)(1 * MB), // 1MB - controls initial frame size for connection - ConnWaitTime: defaultConnWaitTime, - + ConnWaitTime: defaultConnWaitTime, + KeepAliveTime: 30 * time.Minute, KeepAliveTimeout: 30 * time.Minute, AllowWithoutStream: true, - MaxRetries: maxRetries, - RetryWaitTime: defaultRetryWaitTime, - EnableRetries: true, + MaxRetries: maxRetries, + RetryWaitTime: defaultRetryWaitTime, + EnableRetries: true, - BackoffConfig: &defaultBackoffConfig, + BackoffConfig: &defaultBackoffConfig, MinConnectTimeout: 20 * time.Second, } @@ -136,7 +135,7 @@ func DefaultClientOptions() *ClientOptions { type defaultDialOptionsBuilder struct{} // defaultConnectionHandler is the default implementation of ConnectionHandler -type defaultConnectionHandler struct{ +type defaultConnectionHandler struct { client grpcClient } @@ -176,16 +175,16 @@ func (b *defaultDialOptionsBuilder) buildConnectParams(opts *ClientOptions) grpc // NewClient creates a new gRPC client with the given ALTS credentials func NewClient(creds credentials.TransportCredentials) *Client { client := &Client{ - creds: creds, + creds: creds, builder: &defaultDialOptionsBuilder{}, } client.connHandler = &defaultConnectionHandler{client} return client } -// NewClientEx allows injecting a custom DialOptionBuilder and/or +// NewClientEx allows injecting a custom DialOptionBuilder and/or // ConnectionHandler (for testing) -func NewClientEx(creds credentials.TransportCredentials, builder DialOptionBuilder, +func NewClientEx(creds credentials.TransportCredentials, builder DialOptionBuilder, connHandler ConnectionHandler) *Client { if builder == nil { @@ -276,26 +275,27 @@ func (ch *defaultConnectionHandler) attemptConnection(ctx context.Context, targe // Wait for connection to be ready if err := waitForConnection(ctx, gclient, opts.ConnWaitTime); err != nil { gclient.Close() - log.WithContext(ctx).WithError(err).Error("Connection failed") + logtrace.Error(ctx, "Connection failed", logtrace.Fields{"target": target, "error": err}) + return nil, fmt.Errorf("connection failed: %w", err) } - log.WithContext(ctx).Debugf("Connected to %s", target) + logtrace.Debug(ctx, "Connected to gRPC server", logtrace.Fields{"target": target}) return gclient, nil } // retryConnection attempts to connect with retry logic func (ch *defaultConnectionHandler) retryConnection(ctx context.Context, address string, opts *ClientOptions) (*grpc.ClientConn, error) { var lastErr error - + for retries := 0; retries < opts.MaxRetries; retries++ { conn, err := ch.attemptConnection(ctx, address, opts) if err == nil { return conn, nil } - + lastErr = err - + // Check if we should retry if !opts.EnableRetries || retries >= opts.MaxRetries-1 { break @@ -304,10 +304,10 @@ func (ch *defaultConnectionHandler) retryConnection(ctx context.Context, address // Wait before retry, respecting context cancellation select { case <-ctx.Done(): - log.WithContext(ctx).Debugf("Disconnected %s", address) + logtrace.Debug(ctx, "Connection attempt cancelled", logtrace.Fields{"address": address, "retries": retries + 1}) return nil, ctx.Err() case <-time.After(opts.RetryWaitTime): - log.WithContext(ctx).Debugf("Retrying connection to %s (attempt #%d)", address, retries+1) + logtrace.Debug(ctx, "Retrying connection", logtrace.Fields{"address": address, "attempt": retries + 1}) continue } } @@ -315,12 +315,13 @@ func (ch *defaultConnectionHandler) retryConnection(ctx context.Context, address return nil, fmt.Errorf("connection failed after %d attempts: %w", opts.MaxRetries, lastErr) } +// configureContext ensures the context has a timeout and sets up logging // configureContext ensures the context has a timeout and sets up logging func (ch *defaultConnectionHandler) configureContext(ctx context.Context) (context.Context, context.CancelFunc) { - grpclog.SetLoggerV2(log.NewLoggerWithErrorLevel()) + logtrace.SetGRPCLogger(ctx) id, _ := random.String(8, random.Base62Chars) - ctx = log.ContextWithPrefix(ctx, fmt.Sprintf("%s-%s", logPrefix, id)) + ctx = logtrace.CtxWithCorrelationID(ctx, fmt.Sprintf("%s-%s", logPrefix, id)) if _, ok := ctx.Deadline(); !ok { return context.WithTimeout(ctx, defaultTimeout) @@ -338,7 +339,7 @@ func (c *Client) Connect(ctx context.Context, address string, opts *ClientOption if opts == nil { opts = DefaultClientOptions() } - + // Extract identity if in Lumera format remoteIdentity, grpcAddress, err := ltc.ExtractIdentity(address) if err != nil { @@ -412,4 +413,4 @@ client.MonitorConnectionState(ctx, conn, func(state connectivity.State) { log.Println("Connection is shut down") } }) -*/ \ No newline at end of file +*/ diff --git a/pkg/net/grpc/server/server.go b/pkg/net/grpc/server/server.go index 5c189a77..4eca05d4 100644 --- a/pkg/net/grpc/server/server.go +++ b/pkg/net/grpc/server/server.go @@ -13,12 +13,11 @@ import ( "google.golang.org/grpc" "google.golang.org/grpc/credentials" "google.golang.org/grpc/credentials/insecure" - "google.golang.org/grpc/grpclog" "google.golang.org/grpc/keepalive" "google.golang.org/grpc/reflection" "github.com/LumeraProtocol/supernode/pkg/errors" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" ) const ( @@ -204,7 +203,7 @@ func (s *Server) createListener(ctx context.Context, address string) (net.Listen if err != nil { return nil, errors.Errorf("failed to create listener: %w", err).WithField("address", address) } - log.WithContext(ctx).Infof("gRPC server listening on %q", address) + logtrace.Info(ctx, "gRPC server listening", logtrace.Fields{"address": address}) return lis, nil } @@ -218,8 +217,8 @@ func (s *Server) Serve(ctx context.Context, address string, opts *ServerOptions) opts = DefaultServerOptions() } - grpclog.SetLoggerV2(log.NewLoggerWithErrorLevel()) - ctx = log.ContextWithPrefix(ctx, s.name) + logtrace.SetGRPCLogger(ctx) + ctx = logtrace.CtxWithCorrelationID(ctx, s.name) // Create server with options serverOpts := s.buildServerOptions(opts) @@ -257,7 +256,7 @@ func (s *Server) Serve(ctx context.Context, address string, opts *ServerOptions) // Wait for context cancellation or error select { case <-ctx.Done(): - log.WithContext(ctx).Infof("Shutting down gRPC server at %q", address) + logtrace.Info(ctx, "Shutting down gRPC server", logtrace.Fields{"address": address}) return s.Stop(opts.GracefulShutdownTime) case err := <-serveErr: return err diff --git a/pkg/storage/files/file.go b/pkg/storage/files/file.go index d304abe5..4a78cdd3 100644 --- a/pkg/storage/files/file.go +++ b/pkg/storage/files/file.go @@ -2,6 +2,7 @@ package files import ( "bytes" + "context" "fmt" "image" "image/gif" @@ -14,7 +15,7 @@ import ( "time" "github.com/LumeraProtocol/supernode/pkg/errors" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" "github.com/LumeraProtocol/supernode/pkg/storage" "github.com/disintegration/imaging" @@ -329,7 +330,9 @@ func (file *File) UpdateFormat() error { err = file.SetFormatFromExtension(format) if err != nil { - log.WithError(err).Error(fmt.Sprintf("not able to set extension:%s", err.Error())) + logtrace.Error(context.Background(), "not able to set extension", logtrace.Fields{ + logtrace.FieldError: err.Error(), + }) return errors.Errorf("set file format(%s): %w", file.Name(), err) } diff --git a/pkg/storage/fs/file.go b/pkg/storage/fs/file.go index fe9597b8..b400fe4c 100644 --- a/pkg/storage/fs/file.go +++ b/pkg/storage/fs/file.go @@ -1,11 +1,12 @@ package fs import ( + "context" "os" "path/filepath" "github.com/LumeraProtocol/supernode/pkg/errors" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" "github.com/LumeraProtocol/supernode/pkg/storage" ) @@ -38,9 +39,9 @@ func (fs *FS) Create(filename string) (storage.FileInterface, error) { filename = filepath.Join(fs.dir, filename) if _, err := os.Stat(filename); !os.IsNotExist(err) { - log.WithPrefix(logPrefix).Debugf("Rewrite file %q", filename) + logtrace.Debug(context.Background(), "Rewrite file", logtrace.Fields{logtrace.FieldModule: logPrefix, "filename": filename}) } else { - log.WithPrefix(logPrefix).Debugf("Create file %q", filename) + logtrace.Debug(context.Background(), "Create file", logtrace.Fields{logtrace.FieldModule: logPrefix, "filename": filename}) } file, err := os.Create(filename) @@ -54,7 +55,7 @@ func (fs *FS) Create(filename string) (storage.FileInterface, error) { func (fs *FS) Remove(filename string) error { filename = filepath.Join(fs.dir, filename) - log.WithPrefix(logPrefix).Debugf("Remove file %q", filename) + logtrace.Debug(context.Background(), "Remove file", logtrace.Fields{logtrace.FieldModule: logPrefix, "filename": filename}) if err := os.Remove(filename); err != nil { return errors.Errorf("remove file %q: %w", filename, err) @@ -71,7 +72,7 @@ func (fs *FS) Rename(oldname, newname string) error { oldname = filepath.Join(fs.dir, oldname) newname = filepath.Join(fs.dir, newname) - log.WithPrefix(logPrefix).Debugf("Rename file %q to %q", oldname, newname) + logtrace.Debug(context.Background(), "Rename file", logtrace.Fields{logtrace.FieldModule: logPrefix, "old_filename": oldname, "new_filename": newname}) if err := os.Rename(oldname, newname); err != nil { return errors.Errorf("rename file %q to %q: %w", oldname, newname, err) diff --git a/pkg/storage/queries/health_check.go b/pkg/storage/queries/health_check.go index c47db8cf..1a3f4f1c 100644 --- a/pkg/storage/queries/health_check.go +++ b/pkg/storage/queries/health_check.go @@ -5,7 +5,7 @@ import ( "fmt" "time" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" "github.com/LumeraProtocol/supernode/pkg/types" "github.com/LumeraProtocol/supernode/pkg/utils/metrics" json "github.com/json-iterator/go" @@ -98,10 +98,10 @@ func (s *SQLiteStore) GetHCSummaryStats(from time.Time) (hcMetrics metrics.HCMet if err != nil { return hcMetrics, err } - log.WithField("observer_evaluations", len(hcObserversEvaluations)).Info("observer evaluations retrieved") + logtrace.Info(context.Background(), "observer evaluations retrieved", logtrace.Fields{"observer_evaluations": len(hcObserversEvaluations), "from": from}) observerEvaluationMetrics := processHCObserverEvaluations(hcObserversEvaluations) - log.WithField("observer_evaluation_metrics", len(observerEvaluationMetrics)).Info("observer evaluation metrics retrieved") + logtrace.Info(context.Background(), "observer evaluation metrics retrieved", logtrace.Fields{"observer_evaluation_metrics": len(observerEvaluationMetrics), "from": from}) for _, obMetrics := range observerEvaluationMetrics { if obMetrics.ChallengesVerified >= 3 { @@ -154,7 +154,7 @@ func (s *SQLiteStore) GetMetricsDataByHealthCheckChallengeID(ctx context.Context if err != nil { return healthCheckChallengeMessages, err } - log.WithContext(ctx).WithField("rows", len(hcMetrics)).Info("health-check-challenge metrics row count") + logtrace.Info(ctx, "health-check-challenge metrics row count", logtrace.Fields{"rows": len(hcMetrics), "challenge_id": challengeID}) for _, hcMetric := range hcMetrics { msg := types.HealthCheckMessageData{} diff --git a/pkg/storage/queries/self_healing.go b/pkg/storage/queries/self_healing.go index 5a4731f3..ccb25673 100644 --- a/pkg/storage/queries/self_healing.go +++ b/pkg/storage/queries/self_healing.go @@ -5,7 +5,7 @@ import ( "fmt" "time" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" "github.com/LumeraProtocol/supernode/pkg/types" "github.com/LumeraProtocol/supernode/pkg/utils/metrics" json "github.com/json-iterator/go" @@ -257,7 +257,7 @@ func (s *SQLiteStore) GetSHExecutionMetrics(ctx context.Context, from time.Time) if err != nil { return m, err } - log.WithContext(ctx).WithField("rows", len(rows)).Info("self-healing execution metrics row count") + logtrace.Info(ctx, "self-healing execution metrics row count", logtrace.Fields{"rows": len(rows)}) challenges := make(map[string]SHChallengeMetric) for _, row := range rows { @@ -361,12 +361,16 @@ func (s *SQLiteStore) GetSHExecutionMetrics(ctx context.Context, from time.Time) } } - log.WithContext(ctx).WithField("challenges", len(challenges)).Info("self-healing execution metrics challenges count") + logtrace.Info(ctx, "self-healing execution metrics challenges count", logtrace.Fields{"challenges": len(challenges)}) for _, challenge := range challenges { - log.WithContext(ctx).WithField("challenge-id", challenge.ChallengeID).WithField("is-accepted", challenge.IsAccepted). - WithField("is-verified", challenge.IsVerified).WithField("is-healed", challenge.IsHealed). - Info("self-healing challenge metric") + + logtrace.Info(ctx, "self-healing challenge metric", logtrace.Fields{ + "challenge-id": challenge.ChallengeID, + "is-accepted": challenge.IsAccepted, + "is-verified": challenge.IsVerified, + "is-healed": challenge.IsHealed, + }) if challenge.IsAck { m.TotalChallengesAcknowledged++ @@ -471,7 +475,7 @@ func (s *SQLiteStore) GetLastNSHChallenges(ctx context.Context, n int) (types.Se if err != nil { return challenges, err } - log.WithContext(ctx).WithField("rows", len(rows)).Info("self-healing execution metrics row count") + logtrace.Info(ctx, "self-healing execution metrics row count", logtrace.Fields{"rows": len(rows)}) challengesInserted := 0 for _, row := range rows { @@ -503,7 +507,7 @@ func (s *SQLiteStore) GetSHChallengeReport(ctx context.Context, challengeID stri if err != nil { return challenges, err } - log.WithContext(ctx).WithField("rows", len(rows)).Info("self-healing execution metrics row count") + logtrace.Info(ctx, "self-healing execution metrics row count", logtrace.Fields{"rows": len(rows)}) for _, row := range rows { if row.ChallengeID == challengeID { diff --git a/pkg/storage/queries/sqlite.go b/pkg/storage/queries/sqlite.go index c1d4cb02..10ecce79 100644 --- a/pkg/storage/queries/sqlite.go +++ b/pkg/storage/queries/sqlite.go @@ -6,7 +6,7 @@ import ( "path/filepath" "github.com/LumeraProtocol/supernode/pkg/configurer" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" "github.com/jmoiron/sqlx" _ "github.com/mattn/go-sqlite3" //go-sqlite3 ) @@ -291,7 +291,8 @@ type SQLiteStore struct { // CloseHistoryDB closes history database func (s *SQLiteStore) CloseHistoryDB(ctx context.Context) { if err := s.db.Close(); err != nil { - log.WithContext(ctx).WithError(err).Error("error closing history db") + logtrace.Error(ctx, "error closing history db", logtrace.Fields{ + logtrace.FieldError: err.Error()}) } } @@ -391,7 +392,8 @@ func OpenHistoryDB() (LocalStoreInterface, error) { _, err = db.Exec(createPingHistoryWithoutUniqueIPAddress) if err != nil { - log.WithError(err).Error("error executing ping-history w/o unique ip-address constraint migration") + logtrace.Error(context.Background(), "error executing ping-history w/o unique ip-address constraint migration", logtrace.Fields{ + logtrace.FieldError: err.Error()}) } pragmas := []string{ diff --git a/pkg/storage/queries/storage_challenge.go b/pkg/storage/queries/storage_challenge.go index 204fd0cc..cc1aa4ee 100644 --- a/pkg/storage/queries/storage_challenge.go +++ b/pkg/storage/queries/storage_challenge.go @@ -5,7 +5,7 @@ import ( "fmt" "time" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" "github.com/LumeraProtocol/supernode/pkg/types" "github.com/LumeraProtocol/supernode/pkg/utils/metrics" @@ -96,7 +96,10 @@ func (s *SQLiteStore) GetMetricsDataByStorageChallengeID(ctx context.Context, ch if err != nil { return storageChallengeMessages, err } - log.WithContext(ctx).WithField("rows", len(scMetrics)).Info("storage-challenge metrics row count") + // log.WithContext(ctx).WithField("rows", len(scMetrics)).Info("storage-challenge metrics row count") + logtrace.Info(ctx, "storage-challenge metrics row count", logtrace.Fields{ + "rows": len(scMetrics), + }) for _, scMetric := range scMetrics { msg := types.MessageData{} @@ -206,10 +209,16 @@ func (s *SQLiteStore) GetSCSummaryStats(from time.Time) (scMetrics metrics.SCMet if err != nil { return scMetrics, err } - log.WithField("observer_evaluations", len(observersEvaluations)).Info("observer evaluations retrieved") + // log.WithField("observer_evaluations", len(observersEvaluations)).Info("observer evaluations retrieved") + logtrace.Info(context.Background(), "observer evaluations retrieved", logtrace.Fields{ + "observer_evaluations": len(observersEvaluations), + }) observerEvaluationMetrics := processObserverEvaluations(observersEvaluations) - log.WithField("observer_evaluation_metrics", len(observerEvaluationMetrics)).Info("observer evaluation metrics retrieved") + // log.WithField("observer_evaluation_metrics", len(observerEvaluationMetrics)).Info("observer evaluation metrics retrieved") + logtrace.Info(context.Background(), "observer evaluation metrics retrieved", logtrace.Fields{ + "observer_evaluation_metrics": len(observerEvaluationMetrics), + }) for _, obMetrics := range observerEvaluationMetrics { if obMetrics.ChallengesVerified > 2 { diff --git a/pkg/storage/queries/task_history.go b/pkg/storage/queries/task_history.go index 28a8572c..181539cc 100644 --- a/pkg/storage/queries/task_history.go +++ b/pkg/storage/queries/task_history.go @@ -1,9 +1,10 @@ package queries import ( + "context" "fmt" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" "github.com/LumeraProtocol/supernode/pkg/types" json "github.com/json-iterator/go" @@ -57,8 +58,9 @@ func (s *SQLiteStore) QueryTaskHistory(taskID string) (history []types.TaskHisto if details != emptyString { err = json.Unmarshal([]byte(details), &i.Details) if err != nil { - log.Info(details) - log.WithError(err).Error(fmt.Sprintf("cannot unmarshal task history details: %s", details)) + + logtrace.Info(context.Background(), "Detals", logtrace.Fields{"details": details}) + logtrace.Error(context.Background(), fmt.Sprintf("cannot unmarshal task history details: %s", details), logtrace.Fields{"error": err}) i.Details = nil } } diff --git a/pkg/types/types.go b/pkg/types/types.go index 030db278..cb44642d 100644 --- a/pkg/types/types.go +++ b/pkg/types/types.go @@ -1,9 +1,10 @@ package types import ( + "context" "time" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" json "github.com/json-iterator/go" ) @@ -95,11 +96,12 @@ type Details struct { Fields Fields } -// Stringify convert the Details' struct to stringify json func (d *Details) Stringify() string { details, err := json.Marshal(&d) if err != nil { - log.WithError(err).Error("unable to marshal task history details") + logtrace.Error(context.Background(), "unable to marshal task history details", logtrace.Fields{ + logtrace.FieldError: err.Error(), + }) return "" } diff --git a/supernode/cmd/service.go b/supernode/cmd/service.go index 3363e2fb..3f67b1ce 100644 --- a/supernode/cmd/service.go +++ b/supernode/cmd/service.go @@ -5,7 +5,7 @@ import ( "reflect" "github.com/LumeraProtocol/supernode/pkg/errgroup" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" ) type service interface { @@ -21,9 +21,9 @@ func RunServices(ctx context.Context, services ...service) error { group.Go(func() error { err := service.Run(ctx) if err != nil { - log.WithContext(ctx).WithError(err).Errorf("service %s stopped", reflect.TypeOf(service)) + logtrace.Error(ctx, "service stopped with an error", logtrace.Fields{"service": reflect.TypeOf(service).String(), "error": err}) } else { - log.WithContext(ctx).Warnf("service %s stopped", reflect.TypeOf(service)) + logtrace.Info(ctx, "service stopped", logtrace.Fields{"service": reflect.TypeOf(service).String()}) } return err }) diff --git a/supernode/node/supernode/server/server.go b/supernode/node/supernode/server/server.go index efe28924..e4ad906c 100644 --- a/supernode/node/supernode/server/server.go +++ b/supernode/node/supernode/server/server.go @@ -8,13 +8,12 @@ import ( "strings" "google.golang.org/grpc" - "google.golang.org/grpc/grpclog" "google.golang.org/grpc/health" healthpb "google.golang.org/grpc/health/grpc_health_v1" "github.com/LumeraProtocol/lumera/x/lumeraid/securekeyx" "github.com/LumeraProtocol/supernode/pkg/errgroup" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" "github.com/LumeraProtocol/supernode/pkg/lumera" ltc "github.com/LumeraProtocol/supernode/pkg/net/credentials" @@ -43,30 +42,35 @@ func (server *Server) Run(ctx context.Context) error { conn.RegisterALTSRecordProtocols() defer conn.UnregisterALTSRecordProtocols() - grpclog.SetLoggerV2(log.NewLoggerWithErrorLevel()) - log.WithContext(ctx).Infof("Server identity: %s", server.config.Identity) - log.WithContext(ctx).Infof("Listening on: %s", server.config.ListenAddresses) - ctx = log.ContextWithPrefix(ctx, server.name) + + // Add correlation ID to context + ctx = logtrace.CtxWithCorrelationID(ctx, server.name) + + // Set up gRPC logging + logtrace.SetGRPCLogger(ctx) + logtrace.Info(ctx, "Server identity configured", logtrace.Fields{logtrace.FieldModule: "server", "identity": server.config.Identity}) + logtrace.Info(ctx, "Server listening", logtrace.Fields{logtrace.FieldModule: "server", "addresses": server.config.ListenAddresses}) group, ctx := errgroup.WithContext(ctx) addresses := strings.Split(server.config.ListenAddresses, ",") if err := server.setupGRPCServer(); err != nil { + logtrace.Error(ctx, "Failed to setup gRPC server", logtrace.Fields{logtrace.FieldModule: "server", logtrace.FieldError: err.Error()}) return fmt.Errorf("failed to setup gRPC server: %w", err) } // Custom server options opts := grpcserver.DefaultServerOptions() - // Defaul ServerOptions needs to be updated to hanlde larger files - - // opts.GracefulShutdownTime = 60 * time.Second + //TODO : Defaul ServerOptions needs to be updated to hanlde larger files + //EXAMPLE: opts.GracefulShutdownTime = 60 * time.Second for _, address := range addresses { addr := net.JoinHostPort(strings.TrimSpace(address), strconv.Itoa(server.config.Port)) address := addr // Create a new variable to avoid closure issues group.Go(func() error { + logtrace.Info(ctx, "Starting gRPC server", logtrace.Fields{logtrace.FieldModule: "server", "address": address}) return server.grpcServer.Serve(ctx, address, opts) }) } diff --git a/supernode/services/cascade/adaptors/p2p.go b/supernode/services/cascade/adaptors/p2p.go index cd76cfe0..6236830d 100644 --- a/supernode/services/cascade/adaptors/p2p.go +++ b/supernode/services/cascade/adaptors/p2p.go @@ -12,7 +12,6 @@ import ( "time" "github.com/LumeraProtocol/supernode/p2p" - "github.com/LumeraProtocol/supernode/pkg/log" "github.com/LumeraProtocol/supernode/pkg/logtrace" "github.com/LumeraProtocol/supernode/pkg/storage/rqstore" "github.com/LumeraProtocol/supernode/pkg/utils" @@ -97,7 +96,7 @@ func (p *p2pImpl) storeCascadeSymbols(ctx context.Context, taskID, actionID stri sort.Strings(keys) // deterministic order inside the sample } - log.WithContext(ctx).WithField("count", len(keys)).Info("storing RaptorQ symbols") + logtrace.Info(ctx, "storing RaptorQ symbols", logtrace.Fields{"count": len(keys)}) /* stream in fixed-size batches -------------------------------------- */ for start := 0; start < len(keys); { @@ -114,8 +113,10 @@ func (p *p2pImpl) storeCascadeSymbols(ctx context.Context, taskID, actionID stri if err := p.rqStore.UpdateIsFirstBatchStored(actionID); err != nil { return fmt.Errorf("update first-batch flag: %w", err) } - log.WithContext(ctx).WithField("curr-time", time.Now().UTC()).WithField("count", len(keys)). - Info("finished storing RaptorQ symbols") + logtrace.Info(ctx, "finished storing RaptorQ symbols", logtrace.Fields{ + "curr-time": time.Now().UTC(), + "count": len(keys), + }) return nil } @@ -147,7 +148,7 @@ func walkSymbolTree(root string) ([]string, error) { } func (c *p2pImpl) storeSymbolsInP2P(ctx context.Context, taskID, root string, fileKeys []string) error { - log.WithContext(ctx).WithField("count", len(fileKeys)).Info("loading batch symbols") + logtrace.Info(ctx, "loading batch symbols", logtrace.Fields{"count": len(fileKeys)}) symbols, err := utils.LoadSymbols(root, fileKeys) if err != nil { @@ -157,12 +158,12 @@ func (c *p2pImpl) storeSymbolsInP2P(ctx context.Context, taskID, root string, fi if err := c.p2p.StoreBatch(ctx, symbols, common.P2PDataRaptorQSymbol, taskID); err != nil { return fmt.Errorf("p2p store batch: %w", err) } - log.WithContext(ctx).WithField("count", len(symbols)).Info("stored batch symbols") + logtrace.Info(ctx, "stored batch symbols", logtrace.Fields{"count": len(symbols)}) if err := utils.DeleteSymbols(ctx, root, fileKeys); err != nil { return fmt.Errorf("delete symbols: %w", err) } - log.WithContext(ctx).WithField("count", len(symbols)).Info("deleted batch symbols") + logtrace.Info(ctx, "deleted batch symbols", logtrace.Fields{"count": len(symbols)}) return nil } diff --git a/supernode/services/common/service.go b/supernode/services/common/service.go index bb90d9a6..de19a0b2 100644 --- a/supernode/services/common/service.go +++ b/supernode/services/common/service.go @@ -8,7 +8,7 @@ import ( "github.com/LumeraProtocol/supernode/pkg/common/task" "github.com/LumeraProtocol/supernode/pkg/errgroup" "github.com/LumeraProtocol/supernode/pkg/errors" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" ) // SuperNodeServiceInterface common interface for Services @@ -26,7 +26,7 @@ type SuperNodeService struct { // run starts task func (service *SuperNodeService) run(ctx context.Context, nodeID string, prefix string) error { - ctx = log.ContextWithPrefix(ctx, prefix) + ctx = logtrace.CtxWithCorrelationID(ctx, prefix) if nodeID == "" { return errors.New("PastelID is not specified in the config file") @@ -45,14 +45,14 @@ func (service *SuperNodeService) RunHelper(ctx context.Context, nodeID string, p for { select { case <-ctx.Done(): - log.WithContext(ctx).Error("context done - closing sn services") + logtrace.Error(ctx, "context done - closing sn services", logtrace.Fields{logtrace.FieldModule: "supernode"}) return nil case <-time.After(5 * time.Second): if err := service.run(ctx, nodeID, prefix); err != nil { service.Worker = task.NewWorker() - log.WithContext(ctx).WithError(err).Error("Service run failed, retrying") + logtrace.Error(ctx, "Service run failed, retrying", logtrace.Fields{logtrace.FieldModule: "supernode", logtrace.FieldError: err.Error()}) } else { - log.WithContext(ctx).Info("Service run completed successfully - closing sn services") + logtrace.Info(ctx, "Service run completed successfully - closing sn services", logtrace.Fields{logtrace.FieldModule: "supernode"}) return nil } } diff --git a/supernode/services/common/storage_handler.go b/supernode/services/common/storage_handler.go index a69d7b83..078b5297 100644 --- a/supernode/services/common/storage_handler.go +++ b/supernode/services/common/storage_handler.go @@ -13,7 +13,7 @@ import ( "github.com/LumeraProtocol/supernode/p2p" "github.com/LumeraProtocol/supernode/pkg/errors" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" "github.com/LumeraProtocol/supernode/pkg/storage/files" "github.com/LumeraProtocol/supernode/pkg/storage/rqstore" "github.com/LumeraProtocol/supernode/pkg/utils" @@ -67,12 +67,13 @@ func (h *StorageHandler) StoreBytesIntoP2P(ctx context.Context, data []byte, typ // StoreBatch stores into P2P array of bytes arrays func (h *StorageHandler) StoreBatch(ctx context.Context, list [][]byte, typ int) error { - val := ctx.Value(log.TaskIDKey) + val := ctx.Value(logtrace.CorrelationIDKey) taskID := "" if val != nil { taskID = fmt.Sprintf("%v", val) } - log.WithContext(ctx).WithField("task_id", taskID).Info("task_id in storeList") + + logtrace.Info(ctx, "task_id in storeList", logtrace.Fields{logtrace.FieldTaskID: taskID}) return h.P2PClient.StoreBatch(ctx, list, typ, taskID) } @@ -94,7 +95,7 @@ func (h *StorageHandler) StoreRaptorQSymbolsIntoP2P(ctx context.Context, taskID, return err } - /* down-sample if we exceed the “big directory” threshold ------------- */ + /* down-sample if we exceed the "big directory" threshold ------------- */ if len(keys) > loadSymbolsBatchSize { want := int(math.Ceil(float64(len(keys)) * storeSymbolsPercent / 100)) if want < len(keys) { @@ -104,7 +105,7 @@ func (h *StorageHandler) StoreRaptorQSymbolsIntoP2P(ctx context.Context, taskID, sort.Strings(keys) // deterministic order inside the sample } - log.WithContext(ctx).WithField("count", len(keys)).Info("storing RaptorQ symbols") + logtrace.Info(ctx, "storing RaptorQ symbols", logtrace.Fields{"count": len(keys)}) /* stream in fixed-size batches -------------------------------------- */ for start := 0; start < len(keys); { @@ -121,8 +122,8 @@ func (h *StorageHandler) StoreRaptorQSymbolsIntoP2P(ctx context.Context, taskID, if err := h.store.UpdateIsFirstBatchStored(h.TxID); err != nil { return fmt.Errorf("update first-batch flag: %w", err) } - log.WithContext(ctx).WithField("curr-time", time.Now().UTC()).WithField("count", len(keys)). - Info("finished storing RaptorQ symbols") + + logtrace.Info(ctx, "finished storing RaptorQ symbols", logtrace.Fields{"curr-time": time.Now().UTC(), "count": len(keys)}) return nil } @@ -154,7 +155,7 @@ func walkSymbolTree(root string) ([]string, error) { } func (h *StorageHandler) storeSymbolsInP2P(ctx context.Context, taskID, root string, fileKeys []string) error { - log.WithContext(ctx).WithField("count", len(fileKeys)).Info("loading batch symbols") + logtrace.Info(ctx, "loading batch symbols", logtrace.Fields{"count": len(fileKeys)}) symbols, err := utils.LoadSymbols(root, fileKeys) if err != nil { @@ -164,12 +165,14 @@ func (h *StorageHandler) storeSymbolsInP2P(ctx context.Context, taskID, root str if err := h.P2PClient.StoreBatch(ctx, symbols, P2PDataRaptorQSymbol, taskID); err != nil { return fmt.Errorf("p2p store batch: %w", err) } - log.WithContext(ctx).WithField("count", len(symbols)).Info("stored batch symbols") + + logtrace.Info(ctx, "stored batch symbols", logtrace.Fields{"count": len(symbols)}) if err := utils.DeleteSymbols(ctx, root, fileKeys); err != nil { return fmt.Errorf("delete symbols: %w", err) } - log.WithContext(ctx).WithField("count", len(symbols)).Info("deleted batch symbols") + + logtrace.Info(ctx, "deleted batch symbols", logtrace.Fields{"count": len(symbols)}) return nil } diff --git a/supernode/services/common/supernode_task.go b/supernode/services/common/supernode_task.go index ac7184f0..6535e842 100644 --- a/supernode/services/common/supernode_task.go +++ b/supernode/services/common/supernode_task.go @@ -6,7 +6,7 @@ import ( "github.com/LumeraProtocol/supernode/pkg/common/task" "github.com/LumeraProtocol/supernode/pkg/common/task/state" - "github.com/LumeraProtocol/supernode/pkg/log" + "github.com/LumeraProtocol/supernode/pkg/logtrace" "github.com/LumeraProtocol/supernode/pkg/storage/files" ) @@ -23,12 +23,12 @@ type SuperNodeTask struct { // RunHelper common code for Task runner func (task *SuperNodeTask) RunHelper(ctx context.Context, clean TaskCleanerFunc) error { ctx = task.context(ctx) - log.WithContext(ctx).Debug("Start task") - defer log.WithContext(ctx).Info("Task canceled") + logtrace.Debug(ctx, "Start task", logtrace.Fields{}) + defer logtrace.Info(ctx, "Task canceled", logtrace.Fields{}) defer task.Cancel() task.SetStatusNotifyFunc(func(status *state.Status) { - log.WithContext(ctx).WithField("status", status.String()).Debug("States updated") + logtrace.Debug(ctx, "States updated", logtrace.Fields{"status": status.String()}) }) defer clean() @@ -37,15 +37,15 @@ func (task *SuperNodeTask) RunHelper(ctx context.Context, clean TaskCleanerFunc) } func (task *SuperNodeTask) context(ctx context.Context) context.Context { - return log.ContextWithPrefix(ctx, fmt.Sprintf("%s-%s", task.LogPrefix, task.ID())) + return logtrace.CtxWithCorrelationID(ctx, fmt.Sprintf("%s-%s", task.LogPrefix, task.ID())) } // RemoveFile removes file from FS (TODO: move to gonode.common) func (task *SuperNodeTask) RemoveFile(file *files.File) { if file != nil { - log.Debugf("remove file: %s", file.Name()) + logtrace.Debug(context.Background(), "remove file", logtrace.Fields{"filename": file.Name()}) if err := file.Remove(); err != nil { - log.Debugf("remove file failed: %s", err.Error()) + logtrace.Debug(context.Background(), "remove file failed", logtrace.Fields{logtrace.FieldError: err.Error()}) } } }