internal async Task ProcessJoinRequestAsync(LoRaRequest request) { LoRaDevice loRaDevice = null; var loraRegion = request.Region; try { var timeWatcher = request.GetTimeWatcher(); var processingTimeout = timeWatcher.GetRemainingTimeToJoinAcceptSecondWindow() - TimeSpan.FromMilliseconds(100); using var joinAcceptCancellationToken = new CancellationTokenSource(processingTimeout > TimeSpan.Zero ? processingTimeout : TimeSpan.Zero); var joinReq = (LoRaPayloadJoinRequest)request.Payload; var devEui = joinReq.DevEUI; using var scope = this.logger.BeginDeviceScope(devEui); this.logger.LogInformation("join request received"); if (this.concentratorDeduplication.CheckDuplicateJoin(request) is ConcentratorDeduplicationResult.Duplicate) { request.NotifyFailed(loRaDevice, LoRaDeviceRequestFailedReason.DeduplicationDrop); // we do not log here as the concentratorDeduplication service already does more detailed logging return; } loRaDevice = await this.deviceRegistry.GetDeviceForJoinRequestAsync(devEui, joinReq.DevNonce); if (loRaDevice == null) { request.NotifyFailed(devEui.ToString(), LoRaDeviceRequestFailedReason.UnknownDevice); // we do not log here as we assume that the deviceRegistry does a more informed logging if returning null return; } if (loRaDevice.AppKey is null) { this.logger.LogError("join refused: missing AppKey for OTAA device"); request.NotifyFailed(loRaDevice, LoRaDeviceRequestFailedReason.InvalidJoinRequest); return; } var appKey = loRaDevice.AppKey.Value; this.joinRequestCounter?.Add(1); if (loRaDevice.AppEui != joinReq.AppEui) { this.logger.LogError("join refused: AppEUI for OTAA does not match device"); request.NotifyFailed(loRaDevice, LoRaDeviceRequestFailedReason.InvalidJoinRequest); return; } if (!joinReq.CheckMic(appKey)) { this.logger.LogError("join refused: invalid MIC"); request.NotifyFailed(loRaDevice, LoRaDeviceRequestFailedReason.JoinMicCheckFailed); return; } // Make sure that is a new request and not a replay if (loRaDevice.DevNonce is { } devNonce&& devNonce == joinReq.DevNonce) { if (string.IsNullOrEmpty(loRaDevice.GatewayID)) { this.logger.LogInformation("join refused: join already processed by another gateway"); } else { this.logger.LogError("join refused: DevNonce already used by this device"); } request.NotifyFailed(loRaDevice, LoRaDeviceRequestFailedReason.JoinDevNonceAlreadyUsed); return; } // Check that the device is joining through the linked gateway and not another if (!loRaDevice.IsOurDevice) { this.logger.LogInformation("join refused: trying to join not through its linked gateway, ignoring join request"); request.NotifyFailed(loRaDevice, LoRaDeviceRequestFailedReason.HandledByAnotherGateway); return; } var netId = this.configuration.NetId; var appNonce = new AppNonce(RandomNumberGenerator.GetInt32(toExclusive: AppNonce.MaxValue + 1)); var appSKey = OTAAKeysGenerator.CalculateAppSessionKey(appNonce, netId, joinReq.DevNonce, appKey); var nwkSKey = OTAAKeysGenerator.CalculateNetworkSessionKey(appNonce, netId, joinReq.DevNonce, appKey); var address = RandomNumberGenerator.GetInt32(toExclusive: DevAddr.MaxNetworkAddress + 1); // The 7 LBS of the NetID become the NwkID of a DevAddr: var devAddr = new DevAddr(unchecked ((byte)netId.NetworkId), address); var oldDevAddr = loRaDevice.DevAddr; if (!timeWatcher.InTimeForJoinAccept()) { this.receiveWindowMisses?.Add(1); // in this case it's too late, we need to break and avoid saving twins this.logger.LogInformation("join refused: processing of the join request took too long, sending no message"); request.NotifyFailed(loRaDevice, LoRaDeviceRequestFailedReason.ReceiveWindowMissed); return; } var updatedProperties = new LoRaDeviceJoinUpdateProperties { DevAddr = devAddr, NwkSKey = nwkSKey, AppSKey = appSKey, AppNonce = appNonce, DevNonce = joinReq.DevNonce, NetId = netId, Region = request.Region.LoRaRegion, PreferredGatewayID = this.configuration.GatewayID, }; if (loRaDevice.ClassType == LoRaDeviceClassType.C) { updatedProperties.SavePreferredGateway = true; updatedProperties.SaveRegion = true; updatedProperties.StationEui = request.StationEui; } DeviceJoinInfo deviceJoinInfo = null; if (request.Region.LoRaRegion == LoRaRegionType.CN470RP2) { if (request.Region.TryGetJoinChannelIndex(request.RadioMetadata.Frequency, out var channelIndex)) { updatedProperties.CN470JoinChannel = channelIndex; deviceJoinInfo = new DeviceJoinInfo(channelIndex); } else { this.logger.LogError("failed to retrieve the join channel index for device"); } } var deviceUpdateSucceeded = await loRaDevice.UpdateAfterJoinAsync(updatedProperties, joinAcceptCancellationToken.Token); if (!deviceUpdateSucceeded) { this.logger.LogError("join refused: join request could not save twin"); request.NotifyFailed(loRaDevice, LoRaDeviceRequestFailedReason.IoTHubProblem); return; } var windowToUse = timeWatcher.ResolveJoinAcceptWindowToUse(); if (windowToUse is null) { this.receiveWindowMisses?.Add(1); this.logger.LogInformation("join refused: processing of the join request took too long, sending no message"); request.NotifyFailed(loRaDevice, LoRaDeviceRequestFailedReason.ReceiveWindowMissed); return; } this.deviceRegistry.UpdateDeviceAfterJoin(loRaDevice, oldDevAddr); // Build join accept downlink message // Build the DlSettings fields that is a superposition of RX2DR and RX1DROffset field var dlSettings = new byte[1]; if (loRaDevice.DesiredRX2DataRate.HasValue) { if (request.Region.DRtoConfiguration.ContainsKey(loRaDevice.DesiredRX2DataRate.Value)) { dlSettings[0] = (byte)((byte)loRaDevice.DesiredRX2DataRate & 0b00001111); } else { this.logger.LogError("twin RX2 DR value is not within acceptable values"); } } if (request.Region.IsValidRX1DROffset(loRaDevice.DesiredRX1DROffset)) { var rx1droffset = (byte)(loRaDevice.DesiredRX1DROffset << 4); dlSettings[0] = (byte)(dlSettings[0] + rx1droffset); } else { this.logger.LogError("twin RX1 offset DR value is not within acceptable values"); } // The following DesiredRxDelay is different than the RxDelay to be passed to Serialize function // This one is a delay between TX and RX for any message to be processed by joining device // The field accepted by Serialize method is an indication of the delay (compared to receive time of join request) // of when the message Join Accept message should be sent var loraSpecDesiredRxDelay = RxDelay.RxDelay0; if (Enum.IsDefined(loRaDevice.DesiredRXDelay)) { loraSpecDesiredRxDelay = loRaDevice.DesiredRXDelay; } else { this.logger.LogError("twin RX delay value is not within acceptable values"); } var loRaPayloadJoinAccept = new LoRaPayloadJoinAccept( netId, // NETID 0 / 1 is default test devAddr, // todo add device address management appNonce, dlSettings, loraSpecDesiredRxDelay, null); if (!loraRegion.TryGetDownstreamChannelFrequency(request.RadioMetadata.Frequency, upstreamDataRate: request.RadioMetadata.DataRate, deviceJoinInfo: deviceJoinInfo, downstreamFrequency: out var freq)) { this.logger.LogError("could not resolve DR and/or frequency for downstream"); request.NotifyFailed(loRaDevice, LoRaDeviceRequestFailedReason.InvalidUpstreamMessage); return; } var joinAcceptBytes = loRaPayloadJoinAccept.Serialize(appKey); var rx1 = windowToUse is not ReceiveWindow2 ? new ReceiveWindow(loraRegion.GetDownstreamDataRate(request.RadioMetadata.DataRate, loRaDevice.ReportedRX1DROffset), freq) : (ReceiveWindow?)null; var rx2 = new ReceiveWindow(loraRegion.GetDownstreamRX2DataRate(this.configuration.Rx2DataRate, null, deviceJoinInfo, this.logger), loraRegion.GetDownstreamRX2Freq(this.configuration.Rx2Frequency, deviceJoinInfo, this.logger)); var downlinkMessage = new DownlinkMessage(joinAcceptBytes, request.RadioMetadata.UpInfo.Xtime, rx1, rx2, loRaDevice.DevEUI, loraRegion.JoinAcceptDelay1, loRaDevice.ClassType, request.StationEui, request.RadioMetadata.UpInfo.AntennaPreference); this.receiveWindowHits?.Add(1, KeyValuePair.Create(MetricRegistry.ReceiveWindowTagName, (object)windowToUse)); _ = request.DownstreamMessageSender.SendDownstreamAsync(downlinkMessage); request.NotifySucceeded(loRaDevice, downlinkMessage); if (this.logger.IsEnabled(LogLevel.Debug)) { var jsonMsg = JsonConvert.SerializeObject(downlinkMessage); this.logger.LogDebug($"{MacMessageType.JoinAccept} {jsonMsg}"); } else { this.logger.LogInformation("join accepted"); } } catch (Exception ex) when (ExceptionFilterUtility.True(() => this.logger.LogError(ex, $"failed to handle join request. {ex.Message}", LogLevel.Error), () => this.unhandledExceptionCount?.Add(1))) { request.NotifyFailed(loRaDevice, ex); throw; } }
/// <summary> /// Process OTAA join request /// </summary> async Task ProcessJoinRequestAsync(LoRaRequest request) { LoRaDevice loRaDevice = null; string devEUI = null; var loraRegion = request.Region; try { var timeWatcher = new LoRaOperationTimeWatcher(loraRegion, request.StartTime); var joinReq = (LoRaPayloadJoinRequest)request.Payload; byte[] udpMsgForPktForwarder = new byte[0]; devEUI = joinReq.GetDevEUIAsString(); var appEUI = joinReq.GetAppEUIAsString(); var devNonce = joinReq.GetDevNonceAsString(); Logger.Log(devEUI, $"join request received", LogLevel.Information); loRaDevice = await this.deviceRegistry.GetDeviceForJoinRequestAsync(devEUI, appEUI, devNonce); if (loRaDevice == null) { request.NotifyFailed(devEUI, LoRaDeviceRequestFailedReason.UnknownDevice); // we do not log here as we assume that the deviceRegistry does a more informed logging if returning null return; } if (string.IsNullOrEmpty(loRaDevice.AppKey)) { Logger.Log(loRaDevice.DevEUI, "join refused: missing AppKey for OTAA device", LogLevel.Error); request.NotifyFailed(loRaDevice, LoRaDeviceRequestFailedReason.InvalidJoinRequest); return; } if (loRaDevice.AppEUI != appEUI) { Logger.Log(devEUI, "join refused: AppEUI for OTAA does not match device", LogLevel.Error); request.NotifyFailed(loRaDevice, LoRaDeviceRequestFailedReason.InvalidJoinRequest); return; } if (!joinReq.CheckMic(loRaDevice.AppKey)) { Logger.Log(devEUI, "join refused: invalid MIC", LogLevel.Error); request.NotifyFailed(loRaDevice, LoRaDeviceRequestFailedReason.JoinMicCheckFailed); return; } // Make sure that is a new request and not a replay if (!string.IsNullOrEmpty(loRaDevice.DevNonce) && loRaDevice.DevNonce == devNonce) { if (string.IsNullOrEmpty(loRaDevice.GatewayID)) { Logger.Log(devEUI, "join refused: join already processed by another gateway", LogLevel.Information); } else { Logger.Log(devEUI, "join refused: DevNonce already used by this device", LogLevel.Error); } loRaDevice.IsOurDevice = false; request.NotifyFailed(loRaDevice, LoRaDeviceRequestFailedReason.JoinDevNonceAlreadyUsed); return; } // Check that the device is joining through the linked gateway and not another if (!string.IsNullOrEmpty(loRaDevice.GatewayID) && !string.Equals(loRaDevice.GatewayID, this.configuration.GatewayID, StringComparison.InvariantCultureIgnoreCase)) { Logger.Log(devEUI, $"join refused: trying to join not through its linked gateway, ignoring join request", LogLevel.Information); loRaDevice.IsOurDevice = false; request.NotifyFailed(loRaDevice, LoRaDeviceRequestFailedReason.HandledByAnotherGateway); return; } var netIdBytes = BitConverter.GetBytes(this.configuration.NetId); var netId = new byte[3] { netIdBytes[0], netIdBytes[1], netIdBytes[2] }; var appNonce = OTAAKeysGenerator.GetAppNonce(); var appNonceBytes = LoRaTools.Utils.ConversionHelper.StringToByteArray(appNonce); var appKeyBytes = LoRaTools.Utils.ConversionHelper.StringToByteArray(loRaDevice.AppKey); var appSKey = OTAAKeysGenerator.CalculateKey(new byte[1] { 0x02 }, appNonceBytes, netId, joinReq.DevNonce, appKeyBytes); var nwkSKey = OTAAKeysGenerator.CalculateKey(new byte[1] { 0x01 }, appNonceBytes, netId, joinReq.DevNonce, appKeyBytes); var devAddr = OTAAKeysGenerator.GetNwkId(netId); var oldDevAddr = loRaDevice.DevAddr; if (!timeWatcher.InTimeForJoinAccept()) { // in this case it's too late, we need to break and avoid saving twins Logger.Log(devEUI, $"join refused: processing of the join request took too long, sending no message", LogLevel.Information); request.NotifyFailed(loRaDevice, LoRaDeviceRequestFailedReason.ReceiveWindowMissed); return; } var updatedProperties = new LoRaDeviceJoinUpdateProperties { DevAddr = devAddr, NwkSKey = nwkSKey, AppSKey = appSKey, AppNonce = appNonce, DevNonce = devNonce, NetID = ConversionHelper.ByteArrayToString(netId), Region = request.Region.LoRaRegion, PreferredGatewayID = this.configuration.GatewayID, }; if (loRaDevice.ClassType == LoRaDeviceClassType.C) { updatedProperties.SavePreferredGateway = true; updatedProperties.SaveRegion = true; } var deviceUpdateSucceeded = await loRaDevice.UpdateAfterJoinAsync(updatedProperties); if (!deviceUpdateSucceeded) { Logger.Log(devEUI, $"join refused: join request could not save twin", LogLevel.Error); request.NotifyFailed(loRaDevice, LoRaDeviceRequestFailedReason.ApplicationError); return; } var windowToUse = timeWatcher.ResolveJoinAcceptWindowToUse(loRaDevice); if (windowToUse == Constants.INVALID_RECEIVE_WINDOW) { Logger.Log(devEUI, $"join refused: processing of the join request took too long, sending no message", LogLevel.Information); request.NotifyFailed(loRaDevice, LoRaDeviceRequestFailedReason.ReceiveWindowMissed); return; } double freq = 0; string datr = null; uint tmst = 0; if (windowToUse == Constants.RECEIVE_WINDOW_1) { datr = loraRegion.GetDownstreamDR(request.Rxpk); if (!loraRegion.TryGetUpstreamChannelFrequency(request.Rxpk, out freq) || datr == null) { Logger.Log(loRaDevice.DevEUI, "could not resolve DR and/or frequency for downstream", LogLevel.Error); request.NotifyFailed(loRaDevice, LoRaDeviceRequestFailedReason.InvalidRxpk); return; } // set tmst for the normal case tmst = request.Rxpk.Tmst + loraRegion.Join_accept_delay1 * 1000000; } else { Logger.Log(devEUI, $"processing of the join request took too long, using second join accept receive window", LogLevel.Debug); tmst = request.Rxpk.Tmst + loraRegion.Join_accept_delay2 * 1000000; (freq, datr) = loraRegion.GetDownstreamRX2DRAndFreq(devEUI, this.configuration.Rx2DataRate, this.configuration.Rx2DataFrequency, null); } loRaDevice.IsOurDevice = true; this.deviceRegistry.UpdateDeviceAfterJoin(loRaDevice, oldDevAddr); // Build join accept downlink message Array.Reverse(netId); Array.Reverse(appNonceBytes); // Build the DlSettings fields that is a superposition of RX2DR and RX1DROffset field byte[] dlSettings = new byte[1]; if (request.Region.DRtoConfiguration.ContainsKey(loRaDevice.DesiredRX2DataRate)) { dlSettings[0] = (byte)(loRaDevice.DesiredRX2DataRate & 0b00001111); } else { Logger.Log(devEUI, $"twin RX2 DR value is not within acceptable values", LogLevel.Error); } if (request.Region.IsValidRX1DROffset(loRaDevice.DesiredRX1DROffset)) { var rx1droffset = (byte)(loRaDevice.DesiredRX1DROffset << 4); dlSettings[0] = (byte)(dlSettings[0] + rx1droffset); } else { Logger.Log(devEUI, $"twin RX1 offset DR value is not within acceptable values", LogLevel.Error); } ushort rxDelay = 0; if (request.Region.IsValidRXDelay(loRaDevice.DesiredRXDelay)) { rxDelay = loRaDevice.DesiredRXDelay; } else { Logger.Log(devEUI, $"twin RX delay value is not within acceptable values", LogLevel.Error); } var loRaPayloadJoinAccept = new LoRaPayloadJoinAccept( LoRaTools.Utils.ConversionHelper.ByteArrayToString(netId), // NETID 0 / 1 is default test ConversionHelper.StringToByteArray(devAddr), // todo add device address management appNonceBytes, dlSettings, rxDelay, null); var joinAccept = loRaPayloadJoinAccept.Serialize(loRaDevice.AppKey, datr, freq, tmst, devEUI); if (joinAccept != null) { _ = request.PacketForwarder.SendDownstreamAsync(joinAccept); request.NotifySucceeded(loRaDevice, joinAccept); if (Logger.LoggerLevel <= LogLevel.Debug) { var jsonMsg = JsonConvert.SerializeObject(joinAccept); Logger.Log(devEUI, $"{LoRaMessageType.JoinAccept.ToString()} {jsonMsg}", LogLevel.Debug); } else if (Logger.LoggerLevel == LogLevel.Information) { Logger.Log(devEUI, "join accepted", LogLevel.Information); } } } catch (Exception ex) { var deviceId = devEUI ?? ConversionHelper.ByteArrayToString(request.Payload.DevAddr); Logger.Log(deviceId, $"failed to handle join request. {ex.Message}", LogLevel.Error); request.NotifyFailed(loRaDevice, ex); } }