search

Azure / iotedge-lorawan-starterkit

Sample implementation of LoRaWAN components to connect LoRaWAN antenna gateway running IoT Edge directly with Azure IoT.
https://azure.github.io/iotedge-lorawan-starterkit/2.2.1
Other
183 stars 61 forks source link

Configuration Question: Concentrator failing to start while configuring BasicsStation for an AAEON AIOT-IP68 gateway with US-915 frequencies #1378

Closed gerfen closed 2 years ago

gerfen commented 2 years ago

I not sure if this is a bug or a configuration error on my part?

I'm in the process of trying to get an AAEON AIOT-IP68 gateway configured as a Basics Station. I've successfully deployed the basics station module to the device via Azure IoT Hub. I should note that the RESET_PIUN and SPI_DEV values work with the older 1.0 implementation of the kit.

The twin looks like this:

{
    "deviceId": "0242ACFFFE120004",
    "etag": "AAAAAAAAAAI=",
    "deviceEtag": "MTE1NzU4NDQy",
    "status": "enabled",
    "statusUpdateTime": "0001-01-01T00:00:00Z",
    "connectionState": "Disconnected",
    "lastActivityTime": "0001-01-01T00:00:00Z",
    "cloudToDeviceMessageCount": 0,
    "authenticationType": "sas",
    "x509Thumbprint": {
        "primaryThumbprint": null,
        "secondaryThumbprint": null
    },
    "modelId": "",
    "version": 3,
    "properties": {
        "desired": {
            "routerConfig": {
                "NetID": [
                    1
                ],
                "JoinEui": [
                    [
                        "0000000000000000",
                        "FFFFFFFFFFFFFFFF"
                    ]
                ],
                "region": "US902",
                "hwspec": "sx1301/1",
                "freq_range": [
                    902000000,
                    928000000
                ],
                "DRs": [
                    [
                        10,
                        125,
                        0
                    ],
                    [
                        9,
                        125,
                        0
                    ],
                    [
                        8,
                        125,
                        0
                    ],
                    [
                        7,
                        125,
                        0
                    ],
                    [
                        8,
                        500,
                        0
                    ],
                    [
                        0,
                        0,
                        0
                    ],
                    [
                        0,
                        0,
                        0
                    ],
                    [
                        0,
                        0,
                        0
                    ],
                    [
                        12,
                        500,
                        1
                    ],
                    [
                        11,
                        500,
                        1
                    ],
                    [
                        10,
                        500,
                        1
                    ],
                    [
                        9,
                        500,
                        1
                    ],
                    [
                        8,
                        500,
                        1
                    ],
                    [
                        7,
                        500,
                        1
                    ]
                ],
                "sx1301_conf": [
                    {
                        "radio_0": {
                            "enable": true,
                            "freq": 904300000
                        },
                        "radio_1": {
                            "enable": true,
                            "freq": 905000000
                        },
                        "chan_FSK": {
                            "enable": true,
                            "radio": 1,
                            "if": 300000
                        },
                        "chan_Lora_std": {
                            "enable": true,
                            "radio": 0,
                            "if": 300000,
                            "bandwidth": 500000,
                            "spread_factor": 8
                        },
                        "chan_multiSF_0": {
                            "enable": true,
                            "radio": 0,
                            "if": -400000
                        },
                        "chan_multiSF_1": {
                            "enable": true,
                            "radio": 0,
                            "if": -200000
                        },
                        "chan_multiSF_2": {
                            "enable": true,
                            "radio": 0,
                            "if": 0
                        },
                        "chan_multiSF_3": {
                            "enable": true,
                            "radio": 0,
                            "if": 200000
                        },
                        "chan_multiSF_4": {
                            "enable": true,
                            "radio": 1,
                            "if": -300000
                        },
                        "chan_multiSF_5": {
                            "enable": true,
                            "radio": 1,
                            "if": -100000
                        },
                        "chan_multiSF_6": {
                            "enable": true,
                            "radio": 1,
                            "if": 100000
                        },
                        "chan_multiSF_7": {
                            "enable": true,
                            "radio": 1,
                            "if": 300000
                        }
                    }
                ],
                "nocca": true,
                "nodc": true,
                "nodwell": true
            },
            "$metadata": {
                "$lastUpdated": "2022-01-25T01:31:52.7658777Z",
                "$lastUpdatedVersion": 2,
                "routerConfig": {
                    "$lastUpdated": "2022-01-25T01:31:52.7658777Z",
                    "$lastUpdatedVersion": 2,
                    "NetID": {
                        "$lastUpdated": "2022-01-25T01:31:52.7658777Z",
                        "$lastUpdatedVersion": 2
                    },
                    "JoinEui": {
                        "$lastUpdated": "2022-01-25T01:31:52.7658777Z",
                        "$lastUpdatedVersion": 2
                    },
                    "region": {
                        "$lastUpdated": "2022-01-25T01:31:52.7658777Z",
                        "$lastUpdatedVersion": 2
                    },
                    "hwspec": {
                        "$lastUpdated": "2022-01-25T01:31:52.7658777Z",
                        "$lastUpdatedVersion": 2
                    },
                    "freq_range": {
                        "$lastUpdated": "2022-01-25T01:31:52.7658777Z",
                        "$lastUpdatedVersion": 2
                    },
                    "DRs": {
                        "$lastUpdated": "2022-01-25T01:31:52.7658777Z",
                        "$lastUpdatedVersion": 2
                    },
                    "sx1301_conf": {
                        "$lastUpdated": "2022-01-25T01:31:52.7658777Z",
                        "$lastUpdatedVersion": 2
                    },
                    "nocca": {
                        "$lastUpdated": "2022-01-25T01:31:52.7658777Z",
                        "$lastUpdatedVersion": 2
                    },
                    "nodc": {
                        "$lastUpdated": "2022-01-25T01:31:52.7658777Z",
                        "$lastUpdatedVersion": 2
                    },
                    "nodwell": {
                        "$lastUpdated": "2022-01-25T01:31:52.7658777Z",
                        "$lastUpdatedVersion": 2
                    }
                }
            },
            "$version": 2
        },
        "reported": {
            "$metadata": {
                "$lastUpdated": "2022-01-25T01:27:47.4657637Z"
            },
            "$version": 1
        }
    },
    "capabilities": {
        "iotEdge": false
    }
}

I set environment variables like so:

     "modules": {
                    "lorabasicsstation": {
                        "settings": {
                            "image": "nurserysentrycontainerregistry.azurecr.io/lorabasicsstation:2.0.0-beta.2-amd64",
                            "createOptions": ""
                        },
                        "type": "docker",
                        "version": "1.0",
                        "env": {
                            "TC_URI": {
                                "value": "ws://20.112.16.171:5000"
                            },
                            "RESET_PIN": {
                                "value": "430"
                            },
                            "SPI_DEV": {
                                "value": "1"
                            },
                            "SPI_SPEED": {
                                "value": "8" // NB: also tried 2
                            }
                        },
                        "status": "running",
                        "restartPolicy": "always"
                    }
                },

Logs with SPI_SPEED set to 8

Finished resetting the pin
No custom station EUI is set, the basic station will select an EUI
Will start in NO_CUPS mode as no CUPS_URI has been specified.
TC_URI is set to: ws://20.112.16.171:5000
Starting base station...
Spi speed set to 8 mbps
Killing process 20
2022-01-25 02:11:13.638 [SYS:INFO] Logging     : stderr (maxsize=10000000, rotate=3)
2022-01-25 02:11:13.638 [SYS:INFO] Station Ver : 2.0.5(linux/std) 2022-01-20 15:55:19
2022-01-25 02:11:13.638 [SYS:INFO] Package Ver : (null)
2022-01-25 02:11:13.638 [SYS:INFO] proto EUI   : 0:242:ac12:4   (/sys/class/net/eth0/address)
2022-01-25 02:11:13.638 [SYS:INFO] prefix EUI  : ::1    (builtin)
2022-01-25 02:11:13.638 [SYS:INFO] Station EUI : 242:acff:fe12:4
2022-01-25 02:11:13.638 [SYS:INFO] Station home: ./     (builtin)
2022-01-25 02:11:13.638 [SYS:INFO] Station temp: /var/tmp/      (builtin)
2022-01-25 02:11:13.638 [SYS:WARN] Station in NO-CUPS mode
2022-01-25 02:11:13.839 [TCE:INFO] Starting TC engine
2022-01-25 02:11:13.866 [AIO:XDEB] [3] ws_connecting state=1
2022-01-25 02:11:13.866 [AIO:XDEB] [3] ws_connecting state=2
2022-01-25 02:11:13.866 [TCE:INFO] Connecting to INFOS: ws://20.112.16.171:5000
2022-01-25 02:11:13.893 [AIO:XDEB] [3] ws_connecting state=3
2022-01-25 02:11:13.893 [AIO:XDEB] [3|WS] > {"router":"242:acff:fe12:4"}
2022-01-25 02:11:13.921 [AIO:XDEB] [3|WS] < {"router":"242:acff:fe12:4","muxs":"0242:ACFF:FE12:0004","uri":"ws://20.112.16.171:5000/router-data/0242ACFFFE120004"}
2022-01-25 02:11:13.921 [TCE:INFO] Infos: 242:acff:fe12:4 0242:ACFF:FE12:0004 ws://20.112.16.171:5000/router-data/0242ACFFFE120004
2022-01-25 02:11:13.921 [AIO:DEBU] [3] ws_close reason=1000
2022-01-25 02:11:13.921 [AIO:DEBU] [3|WS] Server sent close: reason=1000
2022-01-25 02:11:13.921 [AIO:DEBU] [3] WS connection shutdown...
2022-01-25 02:11:13.951 [AIO:XDEB] [3] ws_connecting state=1
2022-01-25 02:11:13.951 [AIO:XDEB] [3] ws_connecting state=2
2022-01-25 02:11:13.952 [TCE:VERB] Connecting to MUXS...
2022-01-25 02:11:13.977 [AIO:XDEB] [3] ws_connecting state=3
2022-01-25 02:11:13.978 [TCE:VERB] Connected to MUXS.
2022-01-25 02:11:13.978 [AIO:XDEB] [3|WS] > {"msgtype":"version","station":"2.0.5(linux/std)","firmware":null,"package":null,"model":"linux","protocol":2,"features":"rmtsh"}
2022-01-25 02:11:14.005 [AIO:XDEB] [3|WS] < {"msgtype":"router_config","NetID":[1],"JoinEui":[[0,18446744073709551615]],"region":"US902","hwspec":"sx1301/1","freq_range":[902000000,928000000],"DRs":[[10,125,0],[9,125,0],[8,125,0],[7,125,0],[8,500,0],[0,0,0],[0,0,0],[0,0,0],[12,500,1],[11,500,1],[10,500,1],[9,500,1],[8,500,1],[7,500,1]],"sx1301_conf":[{"radio_0":{"enable":true,"freq":904300000},"radio_1":{"enable":true,"freq":905000000},"chan_FSK":{"enable":true,"radio":1,"if":300000},"chan_Lora_std":{
2022-01-25 02:11:14.005 [AIO:XDEB] [3|WS] . "enable":true,"radio":0,"if":300000,"bandwidth":500000,"spread_factor":8},"chan_multiSF_0":{"enable":true,"radio":0,"if":-400000},"chan_multiSF_1":{"enable":true,"radio":0,"if":-200000},"chan_multiSF_2":{"enable":true,"radio":0,"if":0},"chan_multiSF_3":{"enable":true,"radio":0,"if":200000},"chan_multiSF_4":{"enable":true,"radio":1,"if":-300000},"chan_multiSF_5":{"enable":true,"radio":1,"if":-100000},"chan_multiSF_6":{"enable":true,"radio":1,"if":100000},"cha
2022-01-25 02:11:14.005 [AIO:XDEB] [3|WS] . n_multiSF_7":{"enable":true,"radio":1,"if":300000}}],"nocca":true,"nodc":true,"nodwell":true}
2022-01-25 02:11:14.006 [RAL:INFO] Lora gateway library version: Version: 5.0.1;
2022-01-25 02:11:14.006 [RAL:VERB] Connecting to device: /dev/spidev1.0
2022-01-25 02:11:14.006 [RAL:DEBU] SX130x txlut table (0 entries)
2022-01-25 02:11:14.006 [RAL:VERB] SX1301 rxrfchain 0: enable=1 freq=904.3MHz rssi_offset=-166.000000 type=2 tx_enable=1 tx_notch_freq=0
2022-01-25 02:11:14.006 [RAL:VERB] SX1301 rxrfchain 1: enable=1 freq=905.0MHz rssi_offset=-166.000000 type=2 tx_enable=0 tx_notch_freq=0
2022-01-25 02:11:14.006 [RAL:VERB] SX1301 ifchain  0: enable=1 rf_chain=0 freq=-400000 bandwidth=0 datarate=0 sync_word=0/0
2022-01-25 02:11:14.006 [RAL:VERB] SX1301 ifchain  1: enable=1 rf_chain=0 freq=-200000 bandwidth=0 datarate=0 sync_word=0/0
2022-01-25 02:11:14.006 [RAL:VERB] SX1301 ifchain  2: enable=1 rf_chain=0 freq=0 bandwidth=0 datarate=0 sync_word=0/0
2022-01-25 02:11:14.006 [RAL:VERB] SX1301 ifchain  3: enable=1 rf_chain=0 freq=200000 bandwidth=0 datarate=0 sync_word=0/0
2022-01-25 02:11:14.006 [RAL:VERB] SX1301 ifchain  4: enable=1 rf_chain=1 freq=-300000 bandwidth=0 datarate=0 sync_word=0/0
2022-01-25 02:11:14.006 [RAL:VERB] SX1301 ifchain  5: enable=1 rf_chain=1 freq=-100000 bandwidth=0 datarate=0 sync_word=0/0
2022-01-25 02:11:14.006 [RAL:VERB] SX1301 ifchain  6: enable=1 rf_chain=1 freq=100000 bandwidth=0 datarate=0 sync_word=0/0
2022-01-25 02:11:14.006 [RAL:VERB] SX1301 ifchain  7: enable=1 rf_chain=1 freq=300000 bandwidth=0 datarate=0 sync_word=0/0
2022-01-25 02:11:14.006 [RAL:VERB] SX1301 ifchain  8: enable=1 rf_chain=0 freq=300000 bandwidth=1 datarate=4 sync_word=0/0
2022-01-25 02:11:14.006 [RAL:VERB] SX1301 ifchain  9: enable=1 rf_chain=1 freq=300000 bandwidth=0 datarate=0 sync_word=0/0
2022-01-25 02:11:14.006 [RAL:VERB] SX130x LBT not enabled
2022-01-25 02:11:14.006 [RAL:VERB] Station device: /dev/spidev1.0 (PPS capture disabled)
2022-01-25 02:11:14.007 [RAL:ERRO] Concentrator start failed: lgw_start
2022-01-25 02:11:14.007 [RAL:ERRO] ral_config failed with status 0x08
2022-01-25 02:11:14.007 [any:ERRO] Closing connection to muxs - error in s2e_onMsg
2022-01-25 02:11:14.007 [AIO:DEBU] [3] ws_close reason=1000
2022-01-25 02:11:14.007 [AIO:XDEB] [3] ws_closing_w state=5
2022-01-25 02:11:14.007 [AIO:DEBU] Echoing close - reason=1000
2022-01-25 02:11:14.031 [AIO:DEBU] [3|WS] Server sent close: reason=1000
2022-01-25 02:11:14.031 [AIO:DEBU] [3] WS connection shutdown...
2022-01-25 02:11:14.031 [TCE:VERB] Connection to MUXS closed in state -1
2022-01-25 02:11:14.031 [TCE:INFO] INFOS reconnect backoff 10s (retry 1)

Logs with SPI_SPEED set to 2

No custom station EUI is set, the basic station will select an EUI
Will start in NO_CUPS mode as no CUPS_URI has been specified.
TC_URI is set to: ws://20.112.16.171:5000
Starting base station...
Spi speed set to 2 mbps
./start_basicsstation.sh: line 37: /basicstation/station.spispeed2: No such file or directory

And for completeness here are the logs form the network server (lorawannetworkservermodule) - 

Executed endpoint '/router-info HTTP: GET'
Request finished HTTP/1.1 GET http://20.112.16.171:5000/router-info - - - 101 - - 59.0688ms
Connection id "0HMEVKB4PAP2G" disconnecting.
Connection id "0HMEVKB4PAP2G" stopped.
Connection id "0HMEVKB4PAP2G" sending FIN because: "The Socket transport's send loop completed gracefully."
An exception occurred while processing requests: System.Net.WebSockets.WebSocketException (0x80004005): The remote party closed the WebSocket connection without completing the close handshake.
   at System.Net.WebSockets.ManagedWebSocket.ThrowIfEOFUnexpected(Boolean throwOnPrematureClosure)
   at System.Net.WebSockets.ManagedWebSocket.EnsureBufferContainsAsync(Int32 minimumRequiredBytes, CancellationToken cancellationToken, Boolean throwOnPrematureClosure)
   at System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1.StateMachineBox`1.System.Threading.Tasks.Sources.IValueTaskSource.GetResult(Int16 token)
   at System.Net.WebSockets.ManagedWebSocket.ReceiveAsyncPrivate[TResult](Memory`1 payloadBuffer, CancellationToken cancellationToken)
   at System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1.StateMachineBox`1.System.Threading.Tasks.Sources.IValueTaskSource<TResult>.GetResult(Int16 token)
   at System.Net.WebSockets.ManagedWebSocket.CloseAsyncPrivate(WebSocketCloseStatus closeStatus, String statusDescription, CancellationToken cancellationToken)
   at LoRaWan.NetworkServer.BasicsStation.Processors.LnsProtocolMessageProcessor.ProcessIncomingRequestAsync(HttpContext httpContext, Func`4 handler, CancellationToken cancellationToken) in /build/LoRaEngine/modules/LoRaWanNetworkSrvModule/LoRaWan.NetworkServer/BasicsStation/Processors/LnsProtocolMessageProcessor.cs:line 96.
Connection id "0HMEVKB4PAP2G", Request id "0HMEVKB4PAP2G:00000002": An unhandled exception was thrown by the application.
Connection id "0HMEVKB4PAP2H" accepted.
Connection id "0HMEVKB4PAP2H" started.
Request starting HTTP/1.1 GET http://20.112.16.171:5000/router-data/0242ACFFFE120004 - -
1 candidate(s) found for the request path '/router-data/0242ACFFFE120004'
Endpoint '/router-data/{routerId:required} HTTP: GET' with route pattern '/router-data/{routerId:required}' is valid for the request path '/router-data/0242ACFFFE120004'
Request matched endpoint '/router-data/{routerId:required} HTTP: GET'
Executing endpoint '/router-data/{routerId:required} HTTP: GET'
WebSocket connection from 72.0.168.220 established
0242ACFFFE120004 Received 'version' message for station '2.0.5(linux/std)'.
Executed endpoint '/router-data/{routerId:required} HTTP: GET'
Request finished HTTP/1.1 GET http://20.112.16.171:5000/router-data/0242ACFFFE120004 - - - 101 - - 51.3453ms
Connection id "0HMEVKB4PAP2H" disconnecting.
Connection id "0HMEVKB4PAP2H" stopped.
Connection id "0HMEVKB4PAP2H" sending FIN because: "The Socket transport's send loop completed gracefully."
Connection id "0HMEVKB4PAP2H" received FIN.
danigian commented 2 years ago

Hi @gerfen, It seems to me that you are missing some required values in the createOptions section:

 "createOptions": {
        "HostConfig": {
            "NetworkMode": "host",
            "Privileged": true
        },
  "NetworkingConfig": {
        "EndpointsConfig": {
            "host": {}
        }
  }

Could you please double check and let us know?

In addition, please remind that as for previous packet forwarder module, setting SPI SPEED to 2 is only supported for ARM devices (but you should not need this setting)

gerfen commented 2 years ago

@danigian I added the createOptions to the lorabasicsstation module config, which is what I think you were asking me to do.

The StationnEUI is getting regenerated on me. How do I fix the EUI?

gerfen commented 2 years ago

Getting closer. Adding the createOptions resolved the concentrator start failure but I ended up having to create another Device with the generated StationEui.

2022-01-25 18:53:26.570 [TCE:INFO] MUXS reconnect backoff 16s (retry 4)
2022-01-25 18:53:42.597 [AIO:XDEB] [3] ws_connecting state=1
2022-01-25 18:53:42.597 [AIO:XDEB] [3] ws_connecting state=2
2022-01-25 18:53:42.597 [TCE:VERB] Connecting to MUXS...
2022-01-25 18:53:43.651 [AIO:XDEB] [3] ws_connecting state=3
2022-01-25 18:53:43.651 [TCE:VERB] Connected to MUXS.
2022-01-25 18:53:43.651 [AIO:XDEB] [3|WS] > {"msgtype":"version","station":"2.0.5(linux/std)","firmware":null,"package":null,"model":"linux","protocol":2,"features":"rmtsh"}
2022-01-25 18:53:46.391 [AIO:XDEB] [3|WS] < {"msgtype":"router_config","NetID":[1],"JoinEui":[[0,18446744073709551615]],"region":"US902","hwspec":"sx1301/1","freq_range":[902000000,928000000],"DRs":[[10,125,0],[9,125,0],[8,125,0],[7,125,0],[8,500,0],[0,0,0],[0,0,0],[0,0,0],[12,500,1],[11,500,1],[10,500,1],[9,500,1],[8,500,1],[7,500,1]],"sx1301_conf":[{"radio_0":{"enable":true,"freq":904300000},"radio_1":{"enable":true,"freq":905000000},"chan_FSK":{"enable":true,"radio":1,"if":300000},"chan_Lora_std":{
2022-01-25 18:53:46.391 [AIO:XDEB] [3|WS] . "enable":true,"radio":0,"if":300000,"bandwidth":500000,"spread_factor":8},"chan_multiSF_0":{"enable":true,"radio":0,"if":-400000},"chan_multiSF_1":{"enable":true,"radio":0,"if":-200000},"chan_multiSF_2":{"enable":true,"radio":0,"if":0},"chan_multiSF_3":{"enable":true,"radio":0,"if":200000},"chan_multiSF_4":{"enable":true,"radio":1,"if":-300000},"chan_multiSF_5":{"enable":true,"radio":1,"if":-100000},"chan_multiSF_6":{"enable":true,"radio":1,"if":100000},"cha
2022-01-25 18:53:46.391 [AIO:XDEB] [3|WS] . n_multiSF_7":{"enable":true,"radio":1,"if":300000}}],"nocca":true,"nodc":true,"nodwell":true}
2022-01-25 18:53:46.391 [RAL:INFO] Lora gateway library version: Version: 5.0.1;
2022-01-25 18:53:46.391 [RAL:VERB] Connecting to device: /dev/spidev1.0
2022-01-25 18:53:46.392 [RAL:DEBU] SX130x txlut table (0 entries)
2022-01-25 18:53:46.392 [RAL:VERB] SX1301 rxrfchain 0: enable=1 freq=904.3MHz rssi_offset=-166.000000 type=2 tx_enable=1 tx_notch_freq=0
2022-01-25 18:53:46.392 [RAL:VERB] SX1301 rxrfchain 1: enable=1 freq=905.0MHz rssi_offset=-166.000000 type=2 tx_enable=0 tx_notch_freq=0
2022-01-25 18:53:46.392 [RAL:VERB] SX1301 ifchain  0: enable=1 rf_chain=0 freq=-400000 bandwidth=0 datarate=0 sync_word=0/0
2022-01-25 18:53:46.392 [RAL:VERB] SX1301 ifchain  1: enable=1 rf_chain=0 freq=-200000 bandwidth=0 datarate=0 sync_word=0/0
2022-01-25 18:53:46.392 [RAL:VERB] SX1301 ifchain  2: enable=1 rf_chain=0 freq=0 bandwidth=0 datarate=0 sync_word=0/0
2022-01-25 18:53:46.392 [RAL:VERB] SX1301 ifchain  3: enable=1 rf_chain=0 freq=200000 bandwidth=0 datarate=0 sync_word=0/0
2022-01-25 18:53:46.392 [RAL:VERB] SX1301 ifchain  4: enable=1 rf_chain=1 freq=-300000 bandwidth=0 datarate=0 sync_word=0/0
2022-01-25 18:53:46.392 [RAL:VERB] SX1301 ifchain  5: enable=1 rf_chain=1 freq=-100000 bandwidth=0 datarate=0 sync_word=0/0
2022-01-25 18:53:46.392 [RAL:VERB] SX1301 ifchain  6: enable=1 rf_chain=1 freq=100000 bandwidth=0 datarate=0 sync_word=0/0
2022-01-25 18:53:46.392 [RAL:VERB] SX1301 ifchain  7: enable=1 rf_chain=1 freq=300000 bandwidth=0 datarate=0 sync_word=0/0
2022-01-25 18:53:46.392 [RAL:VERB] SX1301 ifchain  8: enable=1 rf_chain=0 freq=300000 bandwidth=1 datarate=4 sync_word=0/0
2022-01-25 18:53:46.392 [RAL:VERB] SX1301 ifchain  9: enable=1 rf_chain=1 freq=300000 bandwidth=0 datarate=0 sync_word=0/0
2022-01-25 18:53:46.392 [RAL:VERB] SX130x LBT not enabled
2022-01-25 18:53:46.392 [RAL:VERB] Station device: /dev/spidev1.0 (PPS capture disabled)
2022-01-25 18:53:49.487 [RAL:VERB] Concentrator started (3s95ms)
2022-01-25 18:53:49.487 [S2E:INFO] Configuring for region: US902 -- 902.0MHz..928.0MHz
2022-01-25 18:53:49.487 [S2E:VERB]   DR0  SF10/BW125
2022-01-25 18:53:49.487 [S2E:VERB]   DR1  SF9/BW125
2022-01-25 18:53:49.487 [S2E:VERB]   DR2  SF8/BW125
2022-01-25 18:53:49.487 [S2E:VERB]   DR3  SF7/BW125
2022-01-25 18:53:49.487 [S2E:VERB]   DR4  SF8/BW500
2022-01-25 18:53:49.487 [S2E:VERB]   DR5  FSK
2022-01-25 18:53:49.487 [S2E:VERB]   DR6  FSK
2022-01-25 18:53:49.487 [S2E:VERB]   DR7  FSK
2022-01-25 18:53:49.487 [S2E:VERB]   DR8  SF12/BW500 (DN only)
2022-01-25 18:53:49.487 [S2E:VERB]   DR9  SF11/BW500 (DN only)
2022-01-25 18:53:49.487 [S2E:VERB]   DR10 SF10/BW500 (DN only)
2022-01-25 18:53:49.487 [S2E:VERB]   DR11 SF9/BW500 (DN only)
2022-01-25 18:53:49.487 [S2E:VERB]   DR12 SF8/BW500 (DN only)
2022-01-25 18:53:49.487 [S2E:VERB]   DR13 SF7/BW500 (DN only)
2022-01-25 18:53:49.487 [S2E:VERB]   DR14 undefined
2022-01-25 18:53:49.487 [S2E:VERB]   DR15 undefined
2022-01-25 18:53:49.487 [S2E:VERB]   TX power: 30.0 dBm EIRP
2022-01-25 18:53:49.488 [S2E:VERB]   JoinEui list: 10 entries
2022-01-25 18:53:49.488 [S2E:VERB]   NetID filter: 00000000-00000000-00000000-00000002
2022-01-25 18:53:49.488 [S2E:VERB]   Dev/test settings: nocca=1 nodc=1 nodwell=1
2022-01-25 18:54:31.500 [SYN:INFO] MCU/SX130X drift stats: min: +1.0ppm  q50: +20.0ppm  q80: -38.1ppm  max: +70.5ppm - threshold q90: -41.4ppm
2022-01-25 18:54:31.500 [SYN:INFO] Mean MCU drift vs SX130X#0: 0.5ppm

I can see the basicsstation connecting to the gateway now....

No PFX is set for the server side authentication. No need to trust any certificate.
No certifiate copied, therefore no update-ca-certificates needed.
Getting properties from module twin...
Hosting starting
Hosting started
Loaded hosting startup assembly LoRaWan.NetworkServer
Hosting environment: Production
Content root path: /app
Now listening on: http://0.0.0.0:5000
Connection id "0HMF06G10H03L" accepted.
Connection id "0HMF06G10H03L" started.
Request starting HTTP/1.1 GET http://20.112.16.171:5000/router-data/024299FFFED2F3E4 - -
Wildcard detected, all requests with hosts will be allowed.
1 candidate(s) found for the request path '/router-data/024299FFFED2F3E4'
Endpoint '/router-data/{routerId:required} HTTP: GET' with route pattern '/router-data/{routerId:required}' is valid for the request path '/router-data/024299FFFED2F3E4'
Request matched endpoint '/router-data/{routerId:required} HTTP: GET'
Executing endpoint '/router-data/{routerId:required} HTTP: GET'
WebSocket connection from 72.0.168.220 established
024299FFFED2F3E4 Received 'version' message for station '2.0.5(linux/std)'.
024299FFFED2F3E4 using iotHub directly, no edgeHub queue
024299FFFED2F3E4 getting device twin
024299FFFED2F3E4 done getting device twin

And I can see a device connect and send messages...

0200D3C1 querying the registry for device
0200D3C1 querying the registry for devices by devAddr 0200D3C1 found 1 devices
0018B20000020E90 using iotHub directly, no edgeHub queue
0018B20000020E90 getting device twin
0018B20000020E90 done getting device twin
0018B20000020E90 Device registered in cache.
0018B20000020E90 converted 16bit FCnt 1 to 32bit FCnt 1
0018B20000020E90 no Deduplication Strategy selected
0018B20000020E90 FunctionBundler request finished preparing.
0018B20000020E90 FunctionBundler request finished preparing.
0018B20000020E90 FunctionBundler request: {"GatewayId":"azure-lora-networkserver","ClientFCntUp":1,"ClientFCntDown":0,"Rssi":-97,"AdrRequest":{"DataRate":0,"RequiredSnr":-15,"PerformADRCalculation":false,"FCntUp":1,"FCntDown":0,"MinTxPowerIndex":13,"GatewayId":"azure-loranetworkserver","ClearCache":false},"FunctionItems":5}
0018B20000020E90 FunctionBundler result: {"DeduplicationResult":null,"AdrResult" :{"NbRepetition":null,"TxPower":null,"DataRate":0,"CanConfirmToDevice":false,"FCntDown":null,"NumberOfFrames":1},"NextFCntDown":1,"PreferredGatewayResult":null}
0018B20000020E90 down frame counter: 1
0018B20000020E90 valid frame counter, msg: 1 server: 0
0018B20000020E90 decoding with: http://decoder/api/DecodeAdeunisFieldTester port: 1
0018B20000020E90 sending message {"time":35747322504196436,"tmms":0,"freq":903.9,"chan":0,"rfch":0,"modu":"LoRa","datr":"SF10BW125","rssi":-97.0,"lsnr":-13.75,"                       data":{"temperature":17,"uplink":2,"downlink":1,"battery":3889,"Rssi":-48,"lsnr"                       :8},"port":1,"fcnt":1,"edgets":1643137289111,"rawdata":"jxECAQ8xMAg=","eui":"0018B20000020E90","gatewayid":"azure-lora-networkserver","stationeui":"024299FFFED2                       F3E4"} to hub
0018B20000020E90 message '{"temperature":17,"uplink":2,"downlink":1,"battery":3889,"Rssi":-48,"lsnr":8}' sent to hub
0018B20000020E90 too late for down message (00:00:02.9693112)
0018B20000020E90 processing time: 00:00:02.9909134
024299FFFED2F3E4 Received 'updf' message: '{"msgtype":"updf","MHdr":128,"DevAddr":33608641,"FCtrl":128,"FCnt":3,"FOpts":"","FPort":1,"FRMPayload":"83287CE410774324","MIC":-1379119988,"RefTime":0.000000,"DR":0,"Freq":905300000,"upinfo":{"rctx":0,"xtime":35747322549184284,"gpstime":0,"fts":-1,"rssi":-109,"snr":-14,"rxtime":1643137333.965535}}'.
0200D3C1 device in cache
0018B20000020E90 converted 16bit FCnt 3 to 32bit FCnt 3
0018B20000020E90 no Deduplication Strategy selected
0018B20000020E90 FunctionBundler request finished preparing.
0018B20000020E90 FunctionBundler request finished preparing.
0018B20000020E90 FunctionBundler request: {"GatewayId":"azure-lora-networkserver","ClientFCntUp":3,"ClientFCntDown":1,"Rssi":-109,"AdrRequest":{"DataRate":0,"Re                       quiredSnr":-15,"PerformADRCalculation":false,"FCntUp":3,"FCntDown":1,"MinTxPowerIndex":13,"GatewayId":"azure-lora-networkserver","ClearCache":false},"FunctionIt                       ems":5}
0018B20000020E90 FunctionBundler result: {"DeduplicationResult":null,"AdrResult"                       :{"NbRepetition":null,"TxPower":null,"DataRate":0,"CanConfirmToDevice":false,"FC                       ntDown":null,"NumberOfFrames":2},"NextFCntDown":2,"PreferredGatewayResult":null}
0018B20000020E90 down frame counter: 2
0018B20000020E90 valid frame counter, msg: 3 server: 1
0018B20000020E90 decoding with: http://decoder/api/DecodeAdeunisFieldTester port: 1
0018B20000020E90 sending message {"time":35747322549184284,"tmms":0,"freq":905.3,"chan":0,"rfch":0,"modu":"LoRa","datr":"SF10BW125","rssi":-109.0,"lsnr":-14.0,"                       data":{"temperature":17,"uplink":4,"downlink":3,"battery":3887,"Rssi":-48,"lsnr":7},"port":1,"fcnt":3,"edgets":1643137333978,"rawdata":"jxEEAw8vMAc=","eui":"0018B20000020E90","gatewayid":"azure-lora-networkserver","stationeui":"024299FFFED2F3E4"} to hub
0018B20000020E90 message '{"temperature":17,"uplink":4,"downlink":3,"battery":3887,"Rssi":-48,"lsnr":7}' sent to hub
0018B20000020E90 checking cloud to device message for 00:00:00.3467050
0018B20000020E90 done checking cloud to device message, found no message
0018B20000020E90 using standard region RX2 datarate DR8
0018B20000020E90 using standard region RX2 frequency 923300000
0018B20000020E90 UnconfirmedDataDown {"DevEui":{"IsValid":true,"AsUInt64":6951112510934672},"LnsRxDelay":0,"DeviceClassType":0,"Xtime":35747322549184284,"AntennaPreference":0,"Rx1":{"DataRate":10,"Frequency":{"AsUInt64":927500000,"InKilo":927500.0,"InMega":927.5,"InGiga":0.9275}},"Rx2":{"DataRate":8,"Frequency":{"AsUInt64":923300000,"InKilo":923300.0,"InMega":923.3,"InGiga":0.9233}},"Data":{"Lengt h":12,"IsEmpty":false},"StationEui":{"IsValid":true,"AsUInt64":162861861309707236}}
0018B20000020E90 UnconfirmedDataDown {"DevEui":{"IsValid":true,"AsUInt64":6951112510934672},"LnsRxDelay":0,"DeviceClassType":0,"Xtime":35747322549184284,"AntennaPreference":0,"Rx1":{"DataRate":10,"Frequency":{"AsUInt64":927500000,"InKilo":927500.0,"InMega":927.5,"InGiga":0.9275}},"Rx2":{"DataRate":8,"Frequency":{"AsUInt64":923300000,"InKilo":923300.0,"InMega":923.3,"InGiga":0.9233}},"Data":{"Length":12,"IsEmpty":false},"StationEui":{"IsValid":true,"AsUInt64":162861861309707236}}
0018B20000020E90 sending message to station with EUI '024299FFFED2F3E4' with diid -1537874467. Payload '60C1D30002A0020046038FA9'.
0018B20000020E90 processing time: 00:00:00.7293867
024299FFFED2F3E4 Received 'dntxed' message: '{"msgtype":"dntxed","seqno":-1537874467,"diid":-1537874467,"DR":10,"Freq":927500000,"DevEui":"00-18-B2-00-00-02-0E-                       90","rctx":0,"xtime":35747322550184284,"txtime":41033.471109,"gpstime":0}'.

Where do I set the StationEui so that it is not auto generated?

gerfen commented 2 years ago

I'm also seeing lots of this in the basics station logs...

2022-01-25 19:17:43.172 [SYN:INFO] MCU/SX130X drift stats: min: +0.5ppm  q50: -7.6ppm  q80: -32.8ppm  max: +40.9ppm - threshold q90: +40.5ppm
2022-01-25 19:17:43.172 [SYN:INFO] Mean MCU drift vs SX130X#0: -1.8ppm
2022-01-25 19:17:43.682 [AIO:XDEB] [3|WS] Ignoring incoming WS PONG
2022-01-25 19:17:45.273 [SYN:VERB] Time sync rejected: quality=378 threshold=348
2022-01-25 19:17:47.374 [SYN:VERB] Time sync rejected: quality=367 threshold=348
2022-01-25 19:17:49.475 [SYN:VERB] Time sync rejected: quality=412 threshold=348
2022-01-25 19:17:51.575 [SYN:VERB] Time sync rejected: quality=386 threshold=348
2022-01-25 19:17:53.676 [SYN:VERB] Time sync rejected: quality=444 threshold=348
2022-01-25 19:17:55.777 [SYN:VERB] Time sync rejected: quality=460 threshold=348
2022-01-25 19:17:57.878 [SYN:VERB] Time sync rejected: quality=458 threshold=348
2022-01-25 19:17:59.979 [SYN:VERB] Time sync rejected: quality=410 threshold=348
2022-01-25 19:18:02.079 [SYN:VERB] Time sync rejected: quality=403 threshold=348
2022-01-25 19:18:04.180 [SYN:INFO] Time sync qualities: min=166 q90=458 max=543 (previous q90=348)
2022-01-25 19:18:04.180 [SYN:VERB] Time sync rejected: quality=543 threshold=458
2022-01-25 19:18:11.533 [SYN:VERB] Time sync rejected: quality=467 threshold=458

Not sure if that is normal or problematic?

danigian commented 2 years ago

Hi @gerfen,

there is the possibility to setup a fixed StationEui by specifying a FIXED_STATION_EUI environment variable in the LoRaBasicsStationModule.

In regards to the Time sync issues, please have a look at this answer on the basicsstation repository: https://github.com/lorabasics/basicstation/issues/41#issuecomment-500751882

gerfen commented 2 years ago

@danigian I've got the StationEUI fixed now. Thanks!.

Regarding the time sync issues, I'll let the system run to see if things get better. TBH, reading through that answer still has me somewhat confused. :)

I'll close and will open a different one for the time sync issue if it continues to be an issue.