From 4bc2ffe061c2f13adc429e3c528805831ec5f57e Mon Sep 17 00:00:00 2001 From: Hylke Visser Date: Fri, 3 Feb 2017 11:09:27 +0100 Subject: [PATCH] =?UTF-8?q?Log=20more=20metadata=20everywhere=20?= =?UTF-8?q?=F0=9F=92=AA?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- api/fields/log_fields.go | 240 +++++++++++++++++++++++++++++++++ core/broker/activation.go | 7 +- core/broker/downlink.go | 7 +- core/broker/uplink.go | 3 +- core/component/grpc.go | 5 +- core/handler/activation.go | 16 +-- core/handler/uplink.go | 7 +- core/router/activation.go | 8 +- core/router/downlink.go | 3 +- core/router/gateway/gateway.go | 4 +- core/router/uplink.go | 3 +- vendor/vendor.json | 30 ++--- 12 files changed, 277 insertions(+), 56 deletions(-) create mode 100644 api/fields/log_fields.go diff --git a/api/fields/log_fields.go b/api/fields/log_fields.go new file mode 100644 index 000000000..ac6d8438a --- /dev/null +++ b/api/fields/log_fields.go @@ -0,0 +1,240 @@ +// Copyright © 2017 The Things Network +// Use of this source code is governed by the MIT license that can be found in the LICENSE file. + +package fields + +import ( + "github.com/TheThingsNetwork/go-utils/log" + "github.com/TheThingsNetwork/ttn/api/gateway" + "github.com/TheThingsNetwork/ttn/api/protocol" + "github.com/TheThingsNetwork/ttn/core/types" +) + +type hasId interface { + GetId() string +} + +type hasServiceName interface { + GetServiceName() string +} + +func fillDiscoveryFields(m interface{}, f log.Fields) { + if m, ok := m.(hasId); ok { + if v := m.GetId(); v != "" { + f["ID"] = v + } + } + if m, ok := m.(hasServiceName); ok { + if v := m.GetServiceName(); v != "" { + f["ServiceName"] = v + } + } +} + +type hasDevId interface { + GetDevId() string +} + +type hasAppId interface { + GetAppId() string +} + +type hasDevEui interface { + GetDevEui() *types.DevEUI +} + +type hasAppEui interface { + GetAppEui() *types.AppEUI +} + +type hasDevAddr interface { + GetDevAddr() *types.DevAddr +} + +func fillIdentifiers(m interface{}, f log.Fields) { + if m, ok := m.(hasDevEui); ok { + if v := m.GetDevEui(); v != nil { + f["DevEUI"] = v + } + } + if m, ok := m.(hasAppEui); ok { + if v := m.GetAppEui(); v != nil { + f["AppEUI"] = v + } + } + if m, ok := m.(hasDevId); ok { + if v := m.GetDevId(); v != "" { + f["DevID"] = v + } + } + if m, ok := m.(hasAppId); ok { + if v := m.GetAppId(); v != "" { + f["AppID"] = v + } + } + if m, ok := m.(hasDevAddr); ok { + if v := m.GetDevAddr(); v != nil { + f["DevAddr"] = v + } + } +} + +type hasProtocolMetadata interface { + GetProtocolMetadata() *protocol.RxMetadata +} + +type hasProtocolConfiguration interface { + GetProtocolConfiguration() *protocol.TxConfiguration +} + +type hasProtocolConfig interface { + GetProtocolConfig() *protocol.TxConfiguration +} + +func fillProtocolConfig(cfg *protocol.TxConfiguration, f log.Fields) { + if lorawan := cfg.GetLorawan(); lorawan != nil { + if v := lorawan.Modulation.String(); v != "" { + f["Modulation"] = v + } + if v := lorawan.DataRate; v != "" { + f["DataRate"] = v + } + if v := lorawan.BitRate; v != 0 { + f["BitRate"] = v + } + if v := lorawan.CodingRate; v != "" { + f["CodingRate"] = v + } + } +} + +func fillProtocol(m interface{}, f log.Fields) { + if m, ok := m.(hasProtocolMetadata); ok { + if meta := m.GetProtocolMetadata(); meta != nil { + if lorawan := meta.GetLorawan(); lorawan != nil { + if v := lorawan.Modulation.String(); v != "" { + f["Modulation"] = v + } + if v := lorawan.DataRate; v != "" { + f["DataRate"] = v + } + if v := lorawan.BitRate; v != 0 { + f["BitRate"] = v + } + if v := lorawan.CodingRate; v != "" { + f["CodingRate"] = v + } + } + } + } + if m, ok := m.(hasProtocolConfiguration); ok { + fillProtocolConfig(m.GetProtocolConfiguration(), f) + } + if m, ok := m.(hasProtocolConfig); ok { + fillProtocolConfig(m.GetProtocolConfig(), f) + } +} + +type hasGatewayConfiguration interface { + GetGatewayConfiguration() *gateway.TxConfiguration +} + +type hasGatewayConfig interface { + GetGatewayConfig() *gateway.TxConfiguration +} + +type hasGatewayMetadata interface { + GetGatewayMetadata() *gateway.RxMetadata +} + +type hasMoreGatewayMetadata interface { + GetGatewayMetadata() []*gateway.RxMetadata +} + +func fillGatewayConfig(cfg *gateway.TxConfiguration, f log.Fields) { + if v := cfg.Frequency; v != 0 { + f["Frequency"] = v + } + if v := cfg.Power; v != 0 { + f["Power"] = v + } +} + +func fillGateway(m interface{}, f log.Fields) { + if m, ok := m.(hasGatewayMetadata); ok { + if meta := m.GetGatewayMetadata(); meta != nil { + if v := meta.GatewayId; v != "" { + f["GatewayID"] = v + } + if v := meta.Frequency; v != 0 { + f["Frequency"] = v + } + if v := meta.Rssi; v != 0 { + f["RSSI"] = v + } + if v := meta.Snr; v != 0 { + f["SNR"] = v + } + } + } + if m, ok := m.(hasMoreGatewayMetadata); ok { + if meta := m.GetGatewayMetadata(); meta != nil { + f["NumGateways"] = len(meta) + } + } + if m, ok := m.(hasGatewayConfiguration); ok { + fillGatewayConfig(m.GetGatewayConfiguration(), f) + } + if m, ok := m.(hasGatewayConfig); ok { + fillGatewayConfig(m.GetGatewayConfig(), f) + } +} + +type hasMessage interface { + GetMessage() *protocol.Message +} + +type hasPayload interface { + GetPayload() []byte +} + +func fillMessage(m interface{}, f log.Fields) { + if m, ok := m.(hasPayload); ok { + f["PayloadSize"] = len(m.GetPayload()) + } + if m, ok := m.(hasMessage); ok { + if m := m.GetMessage(); m != nil { + if lorawan := m.GetLorawan(); lorawan != nil { + if mac := lorawan.GetMacPayload(); mac != nil { + if v := mac.DevAddr; !v.IsEmpty() { + f["DevAddr"] = v + } + if v := len(mac.FrmPayload); v != 0 { + f["AppPayloadSize"] = v + } + if v := mac.FPort; v != 0 { + f["Port"] = v + } + if v := mac.FCnt; v != 0 { + f["Counter"] = v + } + } + if join := lorawan.GetJoinRequestPayload(); join != nil { + f["AppEUI"] = join.AppEui + f["DevEUI"] = join.DevEui + } + } + } + } +} + +// Get a number of log fields for a message, if we're able to extract them +func Get(m interface{}) log.Fields { + fields := log.Fields{} + fillDiscoveryFields(m, fields) + fillIdentifiers(m, fields) + fillGateway(m, fields) + fillProtocol(m, fields) + fillMessage(m, fields) + return fields +} diff --git a/core/broker/activation.go b/core/broker/activation.go index 521e8396d..23e7b27e2 100644 --- a/core/broker/activation.go +++ b/core/broker/activation.go @@ -13,6 +13,7 @@ import ( ttnlog "github.com/TheThingsNetwork/go-utils/log" pb "github.com/TheThingsNetwork/ttn/api/broker" pb_discovery "github.com/TheThingsNetwork/ttn/api/discovery" + "github.com/TheThingsNetwork/ttn/api/fields" pb_handler "github.com/TheThingsNetwork/ttn/api/handler" "github.com/TheThingsNetwork/ttn/api/trace" "github.com/TheThingsNetwork/ttn/utils/errors" @@ -28,11 +29,7 @@ type challengeResponseWithHandler struct { var errDuplicateActivation = errors.New("Not handling duplicate activation on this gateway") func (b *broker) HandleActivation(activation *pb.DeviceActivationRequest) (res *pb.DeviceActivationResponse, err error) { - ctx := b.Ctx.WithFields(ttnlog.Fields{ - "GatewayID": activation.GatewayMetadata.GatewayId, - "AppEUI": *activation.AppEui, - "DevEUI": *activation.DevEui, - }) + ctx := b.Ctx.WithFields(fields.Get(activation)) start := time.Now() deduplicatedActivationRequest := new(pb.DeduplicatedDeviceActivationRequest) deduplicatedActivationRequest.ServerTime = start.UnixNano() diff --git a/core/broker/downlink.go b/core/broker/downlink.go index 1e20212f8..13ff340bc 100644 --- a/core/broker/downlink.go +++ b/core/broker/downlink.go @@ -7,8 +7,8 @@ import ( "strings" "time" - ttnlog "github.com/TheThingsNetwork/go-utils/log" pb "github.com/TheThingsNetwork/ttn/api/broker" + "github.com/TheThingsNetwork/ttn/api/fields" "github.com/TheThingsNetwork/ttn/api/trace" "github.com/TheThingsNetwork/ttn/utils/errors" ) @@ -21,10 +21,7 @@ func (a ByScore) Swap(i, j int) { a[i], a[j] = a[j], a[i] } func (a ByScore) Less(i, j int) bool { return a[i].Score < a[j].Score } func (b *broker) HandleDownlink(downlink *pb.DownlinkMessage) error { - ctx := b.Ctx.WithFields(ttnlog.Fields{ - "DevEUI": *downlink.DevEui, - "AppEUI": *downlink.AppEui, - }) + ctx := b.Ctx.WithFields(fields.Get(downlink)) var err error start := time.Now() defer func() { diff --git a/core/broker/uplink.go b/core/broker/uplink.go index 6d3432acd..b8dea0640 100644 --- a/core/broker/uplink.go +++ b/core/broker/uplink.go @@ -13,6 +13,7 @@ import ( ttnlog "github.com/TheThingsNetwork/go-utils/log" pb "github.com/TheThingsNetwork/ttn/api/broker" pb_discovery "github.com/TheThingsNetwork/ttn/api/discovery" + "github.com/TheThingsNetwork/ttn/api/fields" "github.com/TheThingsNetwork/ttn/api/networkserver" pb_lorawan "github.com/TheThingsNetwork/ttn/api/protocol/lorawan" "github.com/TheThingsNetwork/ttn/api/trace" @@ -25,7 +26,7 @@ import ( const maxFCntGap = 16384 func (b *broker) HandleUplink(uplink *pb.UplinkMessage) (err error) { - ctx := b.Ctx.WithField("GatewayID", uplink.GatewayMetadata.GatewayId) + ctx := b.Ctx.WithFields(fields.Get(uplink)) start := time.Now() deduplicatedUplink := new(pb.DeduplicatedUplinkMessage) deduplicatedUplink.ServerTime = start.UnixNano() diff --git a/core/component/grpc.go b/core/component/grpc.go index 93ea18cb7..539db4373 100644 --- a/core/component/grpc.go +++ b/core/component/grpc.go @@ -6,6 +6,7 @@ package component import ( "github.com/TheThingsNetwork/go-utils/grpc/interceptor" "github.com/TheThingsNetwork/go-utils/log" + "github.com/TheThingsNetwork/ttn/api/fields" "github.com/TheThingsNetwork/ttn/utils/errors" "github.com/mwitkow/go-grpc-middleware" "golang.org/x/net/context" // See https://github.com/grpc/grpc-go/issues/711" @@ -16,7 +17,7 @@ import ( func (c *Component) ServerOptions() []grpc.ServerOption { unaryLog := interceptor.Unary(func(req interface{}, info *grpc.UnaryServerInfo) (log.Interface, string) { - return c.Ctx, "Request" + return c.Ctx.WithFields(fields.Get(req)), "Request" }) unaryErr := func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) { @@ -25,7 +26,7 @@ func (c *Component) ServerOptions() []grpc.ServerOption { return iface, err } - streamLog := interceptor.Stream(func(req interface{}, info *grpc.StreamServerInfo) (log.Interface, string) { + streamLog := interceptor.Stream(func(srv interface{}, info *grpc.StreamServerInfo) (log.Interface, string) { return c.Ctx, "Stream" }) diff --git a/core/handler/activation.go b/core/handler/activation.go index a4bbe46e3..1b8aaad57 100644 --- a/core/handler/activation.go +++ b/core/handler/activation.go @@ -9,6 +9,7 @@ import ( ttnlog "github.com/TheThingsNetwork/go-utils/log" pb_broker "github.com/TheThingsNetwork/ttn/api/broker" + "github.com/TheThingsNetwork/ttn/api/fields" pb "github.com/TheThingsNetwork/ttn/api/handler" "github.com/TheThingsNetwork/ttn/api/trace" "github.com/TheThingsNetwork/ttn/core/handler/device" @@ -71,20 +72,7 @@ func (h *handler) HandleActivationChallenge(challenge *pb_broker.ActivationChall func (h *handler) HandleActivation(activation *pb_broker.DeduplicatedDeviceActivationRequest) (res *pb.DeviceActivationResponse, err error) { appID, devID := activation.AppId, activation.DevId - var appEUI types.AppEUI - if activation.AppEui != nil { - appEUI = *activation.AppEui - } - var devEUI types.DevEUI - if activation.DevEui != nil { - devEUI = *activation.DevEui - } - ctx := h.Ctx.WithFields(ttnlog.Fields{ - "DevEUI": devEUI, - "AppEUI": appEUI, - "AppID": appID, - "DevID": devID, - }) + ctx := h.Ctx.WithFields(fields.Get(activation)) start := time.Now() defer func() { if err != nil { diff --git a/core/handler/uplink.go b/core/handler/uplink.go index d65d4e569..4c3ecde1c 100644 --- a/core/handler/uplink.go +++ b/core/handler/uplink.go @@ -6,8 +6,8 @@ package handler import ( "time" - ttnlog "github.com/TheThingsNetwork/go-utils/log" pb_broker "github.com/TheThingsNetwork/ttn/api/broker" + "github.com/TheThingsNetwork/ttn/api/fields" "github.com/TheThingsNetwork/ttn/api/trace" "github.com/TheThingsNetwork/ttn/core/types" ) @@ -17,10 +17,7 @@ var ResponseDeadline = 100 * time.Millisecond func (h *handler) HandleUplink(uplink *pb_broker.DeduplicatedUplinkMessage) (err error) { appID, devID := uplink.AppId, uplink.DevId - ctx := h.Ctx.WithFields(ttnlog.Fields{ - "AppID": appID, - "DevID": devID, - }) + ctx := h.Ctx.WithFields(fields.Get(uplink)) start := time.Now() defer func() { if err != nil { diff --git a/core/router/activation.go b/core/router/activation.go index ca50d5f68..3b0dbabdc 100644 --- a/core/router/activation.go +++ b/core/router/activation.go @@ -8,8 +8,8 @@ import ( "sync" "time" - ttnlog "github.com/TheThingsNetwork/go-utils/log" pb_broker "github.com/TheThingsNetwork/ttn/api/broker" + "github.com/TheThingsNetwork/ttn/api/fields" pb_protocol "github.com/TheThingsNetwork/ttn/api/protocol" pb_lorawan "github.com/TheThingsNetwork/ttn/api/protocol/lorawan" pb "github.com/TheThingsNetwork/ttn/api/router" @@ -19,11 +19,7 @@ import ( ) func (r *router) HandleActivation(gatewayID string, activation *pb.DeviceActivationRequest) (res *pb.DeviceActivationResponse, err error) { - ctx := r.Ctx.WithFields(ttnlog.Fields{ - "GatewayID": gatewayID, - "AppEUI": *activation.AppEui, - "DevEUI": *activation.DevEui, - }) + ctx := r.Ctx.WithField("GatewayID", gatewayID).WithFields(fields.Get(activation)) start := time.Now() defer func() { if err != nil { diff --git a/core/router/downlink.go b/core/router/downlink.go index 909bef989..81ed1f891 100644 --- a/core/router/downlink.go +++ b/core/router/downlink.go @@ -11,6 +11,7 @@ import ( ttnlog "github.com/TheThingsNetwork/go-utils/log" pb_broker "github.com/TheThingsNetwork/ttn/api/broker" + "github.com/TheThingsNetwork/ttn/api/fields" pb_gateway "github.com/TheThingsNetwork/ttn/api/gateway" pb_protocol "github.com/TheThingsNetwork/ttn/api/protocol" pb_lorawan "github.com/TheThingsNetwork/ttn/api/protocol/lorawan" @@ -34,7 +35,7 @@ func (r *router) SubscribeDownlink(gatewayID string, subscriptionID string) (<-c go func() { ctx.Debug("Activate downlink") for message := range fromSchedule { - ctx.Debug("Send downlink") + ctx.WithFields(fields.Get(message)).Debug("Send downlink") toGateway <- message } ctx.Debug("Deactivate downlink") diff --git a/core/router/gateway/gateway.go b/core/router/gateway/gateway.go index f5e3fbc23..d9b74a060 100644 --- a/core/router/gateway/gateway.go +++ b/core/router/gateway/gateway.go @@ -8,6 +8,7 @@ import ( "time" ttnlog "github.com/TheThingsNetwork/go-utils/log" + "github.com/TheThingsNetwork/ttn/api/fields" pb "github.com/TheThingsNetwork/ttn/api/gateway" pb_monitor "github.com/TheThingsNetwork/ttn/api/monitor" pb_router "github.com/TheThingsNetwork/ttn/api/router" @@ -105,11 +106,12 @@ func (g *Gateway) HandleUplink(uplink *pb_router.UplinkMessage) (err error) { } func (g *Gateway) HandleDownlink(identifier string, downlink *pb_router.DownlinkMessage) (err error) { - ctx := g.Ctx.WithField("Identifier", identifier) + ctx := g.Ctx.WithField("Identifier", identifier).WithFields(fields.Get(downlink)) if err = g.Schedule.Schedule(identifier, downlink); err != nil { ctx.WithError(err).Warn("Could not schedule downlink") return err } + ctx.Debug("Scheduled downlink") clone := *downlink // Avoid race conditions for _, monitor := range g.Monitors.GatewayClients(g.ID) { diff --git a/core/router/uplink.go b/core/router/uplink.go index 50195b9fb..85b5c1bf2 100644 --- a/core/router/uplink.go +++ b/core/router/uplink.go @@ -8,6 +8,7 @@ import ( ttnlog "github.com/TheThingsNetwork/go-utils/log" pb_broker "github.com/TheThingsNetwork/ttn/api/broker" + "github.com/TheThingsNetwork/ttn/api/fields" pb_lorawan "github.com/TheThingsNetwork/ttn/api/protocol/lorawan" pb "github.com/TheThingsNetwork/ttn/api/router" "github.com/TheThingsNetwork/ttn/api/trace" @@ -17,7 +18,7 @@ import ( ) func (r *router) HandleUplink(gatewayID string, uplink *pb.UplinkMessage) (err error) { - ctx := r.Ctx.WithField("GatewayID", gatewayID) + ctx := r.Ctx.WithField("GatewayID", gatewayID).WithFields(fields.Get(uplink)) start := time.Now() defer func() { if err != nil { diff --git a/vendor/vendor.json b/vendor/vendor.json index e887d7d15..e4412a939 100644 --- a/vendor/vendor.json +++ b/vendor/vendor.json @@ -77,44 +77,44 @@ { "checksumSHA1": "FCeptJpMzjDNGH+vammILeR7MsI=", "path": "github.com/TheThingsNetwork/go-utils/encoding", - "revision": "e15b5ceb87979c39b9170a3ec1864fec09e2e392", - "revisionTime": "2017-01-27T08:51:05Z" + "revision": "b1c74458c0d5920fce81a9325401c953d9f0be76", + "revisionTime": "2017-02-03T09:55:37Z" }, { - "checksumSHA1": "r2PGxRMFTm0RQ2xLFN5epifTbOM=", + "checksumSHA1": "+0gbhdbMXwRF/VJFxtRomDmZgEk=", "path": "github.com/TheThingsNetwork/go-utils/grpc/interceptor", - "revision": "e15b5ceb87979c39b9170a3ec1864fec09e2e392", - "revisionTime": "2017-01-27T08:51:05Z" + "revision": "b1c74458c0d5920fce81a9325401c953d9f0be76", + "revisionTime": "2017-02-03T09:55:37Z" }, { "checksumSHA1": "T7iFQUlCUAv4cJNDZC0//46Nbio=", "path": "github.com/TheThingsNetwork/go-utils/handlers/cli", - "revision": "e15b5ceb87979c39b9170a3ec1864fec09e2e392", - "revisionTime": "2017-01-27T08:51:05Z" + "revision": "b1c74458c0d5920fce81a9325401c953d9f0be76", + "revisionTime": "2017-02-03T09:55:37Z" }, { "checksumSHA1": "aXt7ZSqIfsHWBbJPgHFjqtyxyQ0=", "path": "github.com/TheThingsNetwork/go-utils/log", - "revision": "e15b5ceb87979c39b9170a3ec1864fec09e2e392", - "revisionTime": "2017-01-27T08:51:05Z" + "revision": "b1c74458c0d5920fce81a9325401c953d9f0be76", + "revisionTime": "2017-02-03T09:55:37Z" }, { "checksumSHA1": "RdI5upcV6MHSjr5Y9zogYvbeURw=", "path": "github.com/TheThingsNetwork/go-utils/log/apex", - "revision": "e15b5ceb87979c39b9170a3ec1864fec09e2e392", - "revisionTime": "2017-01-27T08:51:05Z" + "revision": "b1c74458c0d5920fce81a9325401c953d9f0be76", + "revisionTime": "2017-02-03T09:55:37Z" }, { "checksumSHA1": "sQ0vy3MCGY1WgK9xldn1V6pMeZk=", "path": "github.com/TheThingsNetwork/go-utils/log/grpc", - "revision": "e15b5ceb87979c39b9170a3ec1864fec09e2e392", - "revisionTime": "2017-01-27T08:51:05Z" + "revision": "b1c74458c0d5920fce81a9325401c953d9f0be76", + "revisionTime": "2017-02-03T09:55:37Z" }, { "checksumSHA1": "kLFTtAVcjZbHXybodGAqJ8wxflY=", "path": "github.com/TheThingsNetwork/go-utils/roots", - "revision": "e15b5ceb87979c39b9170a3ec1864fec09e2e392", - "revisionTime": "2017-01-27T08:51:05Z" + "revision": "b1c74458c0d5920fce81a9325401c953d9f0be76", + "revisionTime": "2017-02-03T09:55:37Z" }, { "checksumSHA1": "nV/tpqju2PSPowf3Pq2RCOUESFY=",