Skip to content

Commit 411e5c7

Browse files
ashraffoudaashraffouda
committed
improve logging
Signed-off-by: Ashraf Fouda <ashraf.m.fouda@gmail.com>
1 parent a10e37d commit 411e5c7

File tree

13 files changed

+137
-11
lines changed

13 files changed

+137
-11
lines changed

‎pkg/container/container.go‎

Lines changed: 8 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -142,7 +142,13 @@ func (c *Module) startup() error {
142142

143143
// Run creates and starts a container
144144
func (c *Module) Run(ns string, data pkg.Container) (id pkg.ContainerID, err error) {
145-
log.Debug().Str("ns", ns).Msg("starting container")
145+
log.Info().
146+
Str("namespace", ns).
147+
Str("name", data.Name).
148+
Str("rootfs", data.RootFS).
149+
Uint("cpu", data.CPU).
150+
Uint64("memory", uint64(data.Memory)).
151+
Msgf("starting container")
146152

147153
// create a new client connected to the default socket path for containerd
148154
client, err := containerd.New(c.containerd)
@@ -570,7 +576,7 @@ func (c *Module) SignalDelete(ns string, id pkg.ContainerID) error {
570576

571577
// Delete stops and remove a container
572578
func (c *Module) Delete(ns string, id pkg.ContainerID) error {
573-
log.Debug().Str("id", string(id)).Str("ns", ns).Msg("delete container")
579+
log.Info().Str("namespace", ns).Str("container-id", string(id)).Msg("deleting container")
574580

575581
client, err := containerd.New(c.containerd)
576582
if err != nil {

‎pkg/flist/cleanup.go‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -111,11 +111,11 @@ func (f *flistModule) cleanUnusedMounts() error {
111111
delete(roTargets, info.Pid)
112112
}
113113
if len(roTargets) == 0 {
114-
log.Debug().Msg("no unused mounts detected")
114+
log.Info().Msg("no unused mounts detected")
115115
}
116116
// cleaning up remaining un-used mounts
117117
for pid, mount := range roTargets {
118-
log.Debug().Int64("source", pid).Msgf("cleaning up mount: %+v", mount)
118+
log.Info().Int64("source", pid).Msgf("cleaning up mount: %+v", mount)
119119
if err := f.system.Unmount(mount.Target, 0); err != nil {
120120
log.Error().Err(err).Str("target", mount.Target).Msg("failed to clean up mount")
121121
continue

‎pkg/network/networker.go‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1068,6 +1068,7 @@ func (n *networker) DeleteNR(wl gridtypes.WorkloadID) error {
10681068
return err
10691069
}
10701070

1071+
log.Info().Str("network-id", string(netID)).Msg("deleting network resource")
10711072
nr := nr.New(netNR, n.myceliumKeyDir)
10721073

10731074
if err := nr.Delete(); err != nil {
@@ -1116,6 +1117,8 @@ func (n *networker) SetPublicConfig(cfg pkg.PublicConfig) error {
11161117
return nil
11171118
}
11181119

1120+
log.Info().Str("ipv4", cfg.IPv4.String()).Str("ipv6", cfg.IPv6.String()).Str("gateway", cfg.GW4.String()).Msg("configuring public network")
1121+
11191122
id := n.identity.NodeID(context.Background())
11201123
_, err = public.EnsurePublicSetup(id, environment.MustGet().PubVlan, &cfg)
11211124
if err != nil {

‎pkg/network/nr/net_resource.go‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -203,6 +203,7 @@ func (nr *NetResource) WGName() (string, error) {
203203
// Create setup the basic components of the network resource
204204
// network namespace, bridge, wireguard interface and veth pair
205205
func (nr *NetResource) Create() error {
206+
log.Info().Str("network-id", nr.ID()).Str("subnet", nr.resource.Subnet.String()).Msg("creating network resource")
206207
log.Debug().Str("nr", nr.String()).Msg("create network resource")
207208

208209
if err := nr.ensureNRBridge(); err != nil {
@@ -604,6 +605,8 @@ func (nr *NetResource) ConfigureWG(privateKey string) error {
604605

605606
// Delete removes all the interfaces and namespaces created by the Create method
606607
func (nr *NetResource) Delete() error {
608+
log.Info().Str("network-id", nr.ID()).Str("subnet", nr.resource.Subnet.String()).Msg("deleting network resource")
609+
607610
netnsName, err := nr.Namespace()
608611
if err != nil {
609612
return err

‎pkg/primitives/zdb/zdb.go‎

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -484,6 +484,13 @@ func (p *Manager) createZdbContainerLight(ctx context.Context, device pkg.Device
484484
}
485485

486486
func (p *Manager) zdbRun(ctx context.Context, name string, rootfs string, cmd string, netns string, volumepath string, socketdir string) error {
487+
log.Info().
488+
Str("zdb-name", name).
489+
Str("network-ns", netns).
490+
Str("volume", volumepath).
491+
Str("rootfs", rootfs).
492+
Msg("starting ZDB container")
493+
487494
cont := stubs.NewContainerModuleStub(p.zbus)
488495

489496
// we do data migration here because this is called

‎pkg/provision/engine.go‎

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -347,6 +347,11 @@ func (e *NativeEngine) Admins() Twins {
347347

348348
// Provision workload
349349
func (e *NativeEngine) Provision(ctx context.Context, deployment gridtypes.Deployment) error {
350+
log.Info().
351+
Uint32("twin", deployment.TwinID).
352+
Uint64("contract", deployment.ContractID).
353+
Msg("scheduling deployment for provision")
354+
350355
if deployment.Version != 0 {
351356
return errors.Wrap(ErrInvalidVersion, "expected version to be 0 on deployment creation")
352357
}
@@ -987,6 +992,8 @@ func (e *NativeEngine) updateDeployment(ctx context.Context, ops []gridtypes.Upg
987992

988993
// DecommissionCached implements the zbus interface
989994
func (e *NativeEngine) DecommissionCached(id string, reason string) error {
995+
log.Info().Str("workload-id", id).Str("reason", reason).Msg("decommissioning cached workload")
996+
990997
globalID := gridtypes.WorkloadID(id)
991998
twin, dlID, name, err := globalID.Parts()
992999
if err != nil {

‎pkg/provision/provisiner.go‎

Lines changed: 11 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,7 @@ import (
66
"fmt"
77

88
"github.com/pkg/errors"
9+
"github.com/rs/zerolog/log"
910
"github.com/threefoldtech/zosbase/pkg/gridtypes"
1011
)
1112

@@ -120,6 +121,8 @@ func (p *mapProvisioner) Initialize(ctx context.Context) error {
120121

121122
// Provision implements provision.Provisioner
122123
func (p *mapProvisioner) Provision(ctx context.Context, wl *gridtypes.WorkloadWithID) (result gridtypes.Result, err error) {
124+
log.Info().Str("workload-id", string(wl.ID)).Str("workload-type", string(wl.Type)).Msg("provisioning workload")
125+
123126
manager, ok := p.managers[wl.Type]
124127
if !ok {
125128
return result, fmt.Errorf("unknown workload type '%s' for reservation id '%s'", wl.Type, wl.ID)
@@ -135,6 +138,8 @@ func (p *mapProvisioner) Provision(ctx context.Context, wl *gridtypes.WorkloadWi
135138

136139
// Decommission implementation for provision.Provisioner
137140
func (p *mapProvisioner) Deprovision(ctx context.Context, wl *gridtypes.WorkloadWithID) error {
141+
log.Info().Str("workload-id", string(wl.ID)).Str("workload-type", string(wl.Type)).Msg("deprovisioning workload")
142+
138143
manager, ok := p.managers[wl.Type]
139144
if !ok {
140145
return fmt.Errorf("unknown workload type '%s' for reservation id '%s'", wl.Type, wl.ID)
@@ -145,6 +150,8 @@ func (p *mapProvisioner) Deprovision(ctx context.Context, wl *gridtypes.Workload
145150

146151
// Pause a workload
147152
func (p *mapProvisioner) Pause(ctx context.Context, wl *gridtypes.WorkloadWithID) (gridtypes.Result, error) {
153+
log.Info().Str("workload-id", string(wl.ID)).Str("workload-type", string(wl.Type)).Msg("pausing workload")
154+
148155
if wl.Result.State != gridtypes.StateOk {
149156
return wl.Result, fmt.Errorf("can only pause workloads in ok state")
150157
}
@@ -172,6 +179,8 @@ func (p *mapProvisioner) Pause(ctx context.Context, wl *gridtypes.WorkloadWithID
172179

173180
// Resume a workload
174181
func (p *mapProvisioner) Resume(ctx context.Context, wl *gridtypes.WorkloadWithID) (gridtypes.Result, error) {
182+
log.Info().Str("workload-id", string(wl.ID)).Str("workload-type", string(wl.Type)).Msg("resuming workload")
183+
175184
if wl.Result.State != gridtypes.StatePaused {
176185
return wl.Result, fmt.Errorf("can only resume workloads in paused state")
177186
}
@@ -198,6 +207,8 @@ func (p *mapProvisioner) Resume(ctx context.Context, wl *gridtypes.WorkloadWithI
198207

199208
// Provision implements provision.Provisioner
200209
func (p *mapProvisioner) Update(ctx context.Context, wl *gridtypes.WorkloadWithID) (result gridtypes.Result, err error) {
210+
log.Info().Str("workload-id", string(wl.ID)).Str("workload-type", string(wl.Type)).Msg("updating workload")
211+
201212
manager, ok := p.managers[wl.Type]
202213
if !ok {
203214
return result, fmt.Errorf("unknown workload type '%s' for reservation id '%s'", wl.Type, wl.ID)

‎pkg/storage_light/storage.go‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -193,7 +193,7 @@ func (s *Module) poolType(pool filesystem.Pool, vm bool) (zos.DeviceType, error)
193193
}
194194

195195
func (s *Module) mountPool(device filesystem.DeviceInfo, vm bool) {
196-
log.Debug().Any("device", device).Msg("mounting device")
196+
log.Info().Str("device", device.Path).Str("label", device.Label).Msg("mounting storage device")
197197

198198
if device.IsPXEPartition() {
199199
log.Debug().Str("device", device.Path).Msg("skip device has 'ZOSPXE' label")
@@ -231,9 +231,11 @@ func (s *Module) mountPool(device filesystem.DeviceInfo, vm bool) {
231231
case zos.SSDDevice:
232232
s.totalSSD += usage.Size
233233
s.ssds = append(s.ssds, pool)
234+
log.Info().Str("device", device.Path).Str("type", "SSD").Str("pool", pool.Name()).Uint64("size", usage.Size).Msg("mounted storage pool")
234235
case zos.HDDDevice:
235236
s.totalHDD += usage.Size
236237
s.hdds = append(s.hdds, pool)
238+
log.Info().Str("device", device.Path).Str("type", "HDD").Str("pool", pool.Name()).Uint64("size", usage.Size).Msg("mounted storage pool")
237239
default:
238240
log.Error().Str("type", string(typ)).Str("device", device.Path).Msg("unknown device type")
239241
}

‎pkg/vm/ch.go‎

Lines changed: 10 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -50,7 +50,7 @@ func (m *Machine) startCloudConsole(ctx context.Context, namespace string, netwo
5050
logs,
5151
}
5252

53-
log.Debug().Msgf("running cloud-console : %+v", args)
53+
log.Info().Str("vm-id", m.ID).Str("namespace", namespace).Str("console-ip", networkAddr.IP.String()).Msgf("starting cloud-console on port %d", port)
5454

5555
cmd := exec.CommandContext(ctx, "busybox", args...)
5656
if err := cmd.Start(); err != nil {
@@ -100,6 +100,7 @@ func (m *Machine) startCloudConsoleLight(ctx context.Context, namespace string,
100100
fmt.Sprint(port),
101101
logs,
102102
}
103+
log.Info().Str("vm-id", m.ID).Str("namespace", namespace).Str("mycelium-ip", mycIp).Msgf("starting cloud-console on port %d", port)
103104
log.Debug().Msgf("running cloud-console : %+v", args)
104105

105106
cmd := exec.CommandContext(ctx, "busybox", args...)
@@ -228,7 +229,8 @@ func (m *Machine) Run(ctx context.Context, socket, logs string) (pkg.MachineInfo
228229
// this.
229230
fullArgs = append(fullArgs, "setsid", chBin)
230231
fullArgs = append(fullArgs, argsList...)
231-
log.Debug().Msgf("ch: %+v", fullArgs)
232+
log.Info().Str("vm-id", m.ID).Uint8("cpu", uint8(m.Config.CPU)).Str("memory", m.Config.Mem.String()).Msg("starting cloud-hypervisor VM")
233+
log.Info().Msgf("ch: %+v", fullArgs)
232234

233235
cmd := exec.CommandContext(ctx, "busybox", fullArgs...)
234236
cmd.Stdout = logFd
@@ -280,6 +282,11 @@ func (m *Machine) Run(ctx context.Context, socket, logs string) (pkg.MachineInfo
280282
if err != nil {
281283
return pkg.MachineInfo{}, errors.Wrapf(err, "failed to Inspect vm with id: '%s'", m.ID)
282284
}
285+
286+
logEvent := log.Info().Str("vm-id", m.ID)
287+
logEvent = logInterfaceDetails(logEvent, m.Interfaces, m.NetworkInfo)
288+
logEvent.Msg("VM started with network interfaces and addresses")
289+
283290
consoleURL := ""
284291
for _, ifc := range m.Interfaces {
285292
if ifc.Console != nil {
@@ -323,7 +330,7 @@ func (m *Machine) waitAndAdjOom(ctx context.Context, name string, socket string)
323330
ctx,
324331
),
325332
func(err error, d time.Duration) {
326-
log.Debug().Err(err).Str("id", name).Msg("vm is not up yet")
333+
log.Info().Err(err).Str("id", name).Msg("vm is not up yet")
327334
}); err != nil {
328335

329336
return err

‎pkg/vm/log_helpers.go‎

Lines changed: 44 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,44 @@
1+
package vm
2+
3+
import (
4+
"fmt"
5+
6+
"github.com/rs/zerolog"
7+
"github.com/threefoldtech/zosbase/pkg"
8+
)
9+
10+
func logInterfaceDetails(logEvent *zerolog.Event, interfaces []Interface, networkInfo *pkg.VMNetworkInfo) *zerolog.Event {
11+
for idx, ifc := range interfaces {
12+
logEvent = logEvent.
13+
Str(fmt.Sprintf("interface-%d-id", idx), ifc.ID).
14+
Str(fmt.Sprintf("interface-%d-tap", idx), ifc.Tap).
15+
Str(fmt.Sprintf("interface-%d-mac", idx), ifc.Mac)
16+
17+
if networkInfo != nil && idx < len(networkInfo.Ifaces) {
18+
vmIface := networkInfo.Ifaces[idx]
19+
20+
for ipIdx, ip := range vmIface.IPs {
21+
logEvent = logEvent.Str(fmt.Sprintf("interface-%d-ip-%d", idx, ipIdx), ip.String())
22+
}
23+
24+
if vmIface.IP4DefaultGateway != nil {
25+
logEvent = logEvent.Str(fmt.Sprintf("interface-%d-ipv4-gateway", idx), vmIface.IP4DefaultGateway.String())
26+
}
27+
if vmIface.IP6DefaultGateway != nil {
28+
logEvent = logEvent.Str(fmt.Sprintf("interface-%d-ipv6-gateway", idx), vmIface.IP6DefaultGateway.String())
29+
}
30+
31+
if vmIface.PublicIPv4 {
32+
logEvent = logEvent.Bool(fmt.Sprintf("interface-%d-public-ipv4", idx), true)
33+
}
34+
if vmIface.PublicIPv6 {
35+
logEvent = logEvent.Bool(fmt.Sprintf("interface-%d-public-ipv6", idx), true)
36+
}
37+
38+
if vmIface.NetID != "" {
39+
logEvent = logEvent.Str(fmt.Sprintf("interface-%d-network-id", idx), string(vmIface.NetID))
40+
}
41+
}
42+
}
43+
return logEvent
44+
}

0 commit comments

Comments
 (0)