Announcement

Collapse
No announcement yet.

xPico drops off the network, thinks everything is fine

Collapse
X
  • Filter
  • Time
  • Show
Clear All
new posts

  • xPico drops off the network, thinks everything is fine

    Hi,
    I am observing a strange issue: After some time the xPico module drops off the network (won't respond to ping or discovery packets anymore, doesn't accept connections, no Web Interface) while on the xPico side everything seems fine (nothing unusual in the log - unfortunately I don't have such lock atm but will provide it the next time the issue happens).

    The problem occurs pretty randomly, sometimes after a day of operation. DHCP renew sometimes remedies the issue for a short while.

    The xPico module is connected to a WiFi router and gets an address via DHCP. In the router, the lease time is not expired, I've experimented with different lase times without any noticeable result. This also happened with different routers.

    I'm using Line 1 in Mux mode and listen on all 4 instances.

    I'm using firmware version 1.4.0.0R28

    I will provide more details on the issue should I be able to obtain them, or narrow down the circumstances under which this happens.

  • #2
    Unfortunately the ping command is very unreliable to detect this issue.

    Even when the connection is stable and with no issues, ping will report a rtt of 0ms with TTL = N/A for about 50% of it's invocations.
    2017-04-27 16:41:25,129 - INFO # status Diagnostics Ping>ping 192.168.1.1 2 2
    2017-04-27 16:41:25,129 - INFO #
    2017-04-27 16:41:25,193 - INFO # Sending 2 64-byte ICMP echoes to 192.168.1.1, timeout 2 seconds:
    2017-04-27 16:41:25,193 - INFO #
    2017-04-27 16:41:25,240 - INFO # Reply from 192.168.1.1: time=1ms TTL=64
    2017-04-27 16:41:25,241 - INFO #
    2017-04-27 16:41:27,293 - INFO # Reply from 192.168.1.1: time=1ms TTL=64
    2017-04-27 16:41:27,293 - INFO #
    2017-04-27 16:41:29,298 - INFO #
    2017-04-27 16:41:29,298 - INFO #
    2017-04-27 16:41:29,330 - INFO # Ping Statistics for 192.168.1.1:
    2017-04-27 16:41:29,330 - INFO #
    2017-04-27 16:41:29,393 - INFO # Packets: Sent = 2, Received = 2, Lost = 0 (0% loss),
    2017-04-27 16:41:29,394 - INFO #
    2017-04-27 16:41:29,441 - INFO # Approximate round trip times in milliseconds:
    2017-04-27 16:41:29,441 - INFO #
    2017-04-27 16:41:29,489 - INFO # Minimum = 1ms, Maximum = 1ms, Average = 1ms
    2017-04-27 16:41:29,489 - INFO #
    2017-04-27 16:41:29,489 - INFO #
    2017-04-27 16:41:29,489 - INFO #
    xpico_cli ping 192.168.1.1 2 2
    2017-04-27 16:41:30,141 - INFO # status Diagnostics Ping>ping 192.168.1.1 2 2
    2017-04-27 16:41:30,141 - INFO #
    2017-04-27 16:41:30,205 - INFO # Sending 2 64-byte ICMP echoes to 192.168.1.1, timeout 2 seconds:
    2017-04-27 16:41:30,205 - INFO #
    2017-04-27 16:41:30,253 - INFO # Reply from 192.168.1.1: time=0ms TTL=N/A
    2017-04-27 16:41:30,253 - INFO #
    2017-04-27 16:41:32,305 - INFO # Reply from 192.168.1.1: time=0ms TTL=N/A
    2017-04-27 16:41:32,305 - INFO #
    2017-04-27 16:41:34,310 - INFO #
    2017-04-27 16:41:34,310 - INFO #
    2017-04-27 16:41:34,342 - INFO # Ping Statistics for 192.168.1.1:
    2017-04-27 16:41:34,342 - INFO #
    2017-04-27 16:41:34,406 - INFO # Packets: Sent = 2, Received = 2, Lost = 0 (0% loss),
    2017-04-27 16:41:34,406 - INFO #
    2017-04-27 16:41:34,453 - INFO # Approximate round trip times in milliseconds:
    2017-04-27 16:41:34,454 - INFO #
    2017-04-27 16:41:34,501 - INFO # Minimum = 0ms, Maximum = 0ms, Average = N/A ms
    2017-04-27 16:41:34,517 - INFO #
    2017-04-27 16:41:34,517 - INFO #
    2017-04-27 16:41:34,517 - INFO #
    xpico_cli ping 192.168.1.1 2 2
    2017-04-27 16:41:36,951 - INFO # status Diagnostics Ping>ping 192.168.1.1 2 2
    2017-04-27 16:41:36,952 - INFO #
    2017-04-27 16:41:37,031 - INFO # Sending 2 64-byte ICMP echoes to 192.168.1.1, timeout 2 seconds:
    2017-04-27 16:41:37,031 - INFO #
    2017-04-27 16:41:37,079 - INFO # Reply from 192.168.1.1: time=5ms TTL=64
    2017-04-27 16:41:37,079 - INFO #
    2017-04-27 16:41:39,116 - INFO # Reply from 192.168.1.1: time=1ms TTL=64
    2017-04-27 16:41:39,116 - INFO #
    2017-04-27 16:41:41,120 - INFO #
    2017-04-27 16:41:41,120 - INFO #
    2017-04-27 16:41:41,152 - INFO # Ping Statistics for 192.168.1.1:
    2017-04-27 16:41:41,152 - INFO #
    2017-04-27 16:41:41,216 - INFO # Packets: Sent = 2, Received = 2, Lost = 0 (0% loss),
    2017-04-27 16:41:41,216 - INFO #
    2017-04-27 16:41:41,264 - INFO # Approximate round trip times in milliseconds:
    2017-04-27 16:41:41,264 - INFO #
    2017-04-27 16:41:41,311 - INFO # Minimum = 1ms, Maximum = 5ms, Average = 3ms
    2017-04-27 16:41:41,327 - INFO #
    2017-04-27 16:41:41,327 - INFO #
    2017-04-27 16:41:41,327 - INFO #
    xpico_cli ping 192.168.1.1 3 5
    2017-04-27 16:41:48,726 - INFO # status Diagnostics Ping>ping 192.168.1.1 3 5
    2017-04-27 16:41:48,726 - INFO #
    2017-04-27 16:41:48,790 - INFO # Sending 5 64-byte ICMP echoes to 192.168.1.1, timeout 3 seconds:
    2017-04-27 16:41:48,790 - INFO #
    2017-04-27 16:41:48,837 - INFO # Reply from 192.168.1.1: time=3ms TTL=64
    2017-04-27 16:41:48,838 - INFO #
    2017-04-27 16:41:51,877 - INFO # Reply from 192.168.1.1: time=4ms TTL=64
    2017-04-27 16:41:51,877 - INFO #
    2017-04-27 16:41:54,916 - INFO # Reply from 192.168.1.1: time=1ms TTL=64
    2017-04-27 16:41:54,916 - INFO #
    2017-04-27 16:41:57,970 - INFO # Reply from 192.168.1.1: time=1ms TTL=64
    2017-04-27 16:41:57,971 - INFO #
    2017-04-27 16:42:01,009 - INFO # Reply from 192.168.1.1: time=5ms TTL=64
    2017-04-27 16:42:01,010 - INFO #
    2017-04-27 16:42:04,017 - INFO #
    2017-04-27 16:42:04,017 - INFO #
    2017-04-27 16:42:04,049 - INFO # Ping Statistics for 192.168.1.1:
    2017-04-27 16:42:04,049 - INFO #
    2017-04-27 16:42:04,112 - INFO # Packets: Sent = 5, Received = 5, Lost = 0 (0% loss),
    2017-04-27 16:42:04,112 - INFO #
    2017-04-27 16:42:04,160 - INFO # Approximate round trip times in milliseconds:
    2017-04-27 16:42:04,160 - INFO #
    2017-04-27 16:42:04,208 - INFO # Minimum = 1ms, Maximum = 5ms, Average = 2ms
    2017-04-27 16:42:04,208 - INFO #
    2017-04-27 16:42:04,208 - INFO #
    2017-04-27 16:42:04,208 - INFO #
    xpico_cli ping 192.168.1.1 3 5
    2017-04-27 16:42:04,971 - INFO # status Diagnostics Ping>ping 192.168.1.1 3 5
    2017-04-27 16:42:04,971 - INFO #
    2017-04-27 16:42:05,051 - INFO # Sending 5 64-byte ICMP echoes to 192.168.1.1, timeout 3 seconds:
    2017-04-27 16:42:05,051 - INFO #
    2017-04-27 16:42:05,099 - INFO # Reply from 192.168.1.1: time=0ms TTL=N/A
    2017-04-27 16:42:05,099 - INFO #
    2017-04-27 16:42:08,138 - INFO # Reply from 192.168.1.1: time=0ms TTL=N/A
    2017-04-27 16:42:08,138 - INFO #
    2017-04-27 16:42:11,177 - INFO # Reply from 192.168.1.1: time=0ms TTL=N/A
    2017-04-27 16:42:11,177 - INFO #
    2017-04-27 16:42:14,232 - INFO # Reply from 192.168.1.1: time=0ms TTL=N/A
    2017-04-27 16:42:14,232 - INFO #
    2017-04-27 16:42:17,271 - INFO # Reply from 192.168.1.1: time=0ms TTL=N/A

    Comment


    • #3
      Since you have access to the Mux, there's a few more debugging information you can get.

      Type D to get into the CLI. Then from there you can type tlog to get the logs. Can you see if there's any issues there? Also in the status->diagnostic level, you can see the buffer pools.

      But you might be better off using a 1.5 firmware, as there have been many bug fixes since the 1.4 release.

      Here's the latest Alpha to use:
      http://forums.lantronix.com/showthread.php?t=1337

      Comment


      • #4
        I have a log of when the issue occured: tlog

        But no Output of Buffer Pools yet. Under normal operation it looks like this.

        2017-05-02 11:14:56,542 - INFO # status Diagnostics Buffer Pools>show
        2017-05-02 11:14:56,542 - INFO #
        2017-05-02 11:14:56,574 - INFO # Diagnostics Buffer Pools Status:
        2017-05-02 11:14:56,574 - INFO #
        2017-05-02 11:14:56,669 - INFO # Buffer Pool Transmit
        2017-05-02 11:14:56,670 - INFO #
        2017-05-02 11:14:56,685 - INFO # Total: 10
        2017-05-02 11:14:56,686 - INFO #
        2017-05-02 11:14:56,686 - INFO # Free : 10
        2017-05-02 11:14:56,701 - INFO #
        2017-05-02 11:14:56,781 - INFO # Buffer Pool Receive
        2017-05-02 11:14:56,781 - INFO #
        2017-05-02 11:14:56,797 - INFO # Total: 14
        2017-05-02 11:14:56,797 - INFO #
        2017-05-02 11:14:56,813 - INFO # Free : 14
        The module only accepts incoming connections and doesn't do any outgoing connections on it's own (except for NTP, but that's beyond my control). When the Issue occurred, nobody was talking to the module.
        I've let a script connect to the module every 10 minutes over the weekend, there it was unavailable from Saturday 18:11:40 till Sunday 01:14:01

        Last time I manually saw the issue, I only logged the socket and thread information, but that looked normal.

        2017-04-27 10:23:31,496 - INFO # status Diagnostics IP Sockets>show
        2017-04-27 10:23:31,497 - INFO #
        2017-04-27 10:23:31,529 - INFO # Diagnostics IP Sockets Status:
        2017-04-27 10:23:31,530 - INFO #
        2017-04-27 10:23:31,602 - INFO # IP Socket 1 : UDP, 0, 0, ap0: 67, - , Listen
        2017-04-27 10:23:31,603 - INFO #
        2017-04-27 10:23:31,674 - INFO # IP Socket 2 : UDP, 0, 0, ap0: 53, - , Listen
        2017-04-27 10:23:31,675 - INFO #
        2017-04-27 10:23:31,746 - INFO # IP Socket 3 : TCP, 0, 0, ap0: 80, - , Listen
        2017-04-27 10:23:31,747 - INFO #
        2017-04-27 10:23:31,817 - INFO # IP Socket 4 : TCP, 0, 0, ap0: 5555, - , Listen
        2017-04-27 10:23:31,818 - INFO #
        2017-04-27 10:23:31,889 - INFO # IP Socket 5 : TCP, 0, 0, ap0: 5556, - , Listen
        2017-04-27 10:23:31,890 - INFO #
        2017-04-27 10:23:31,961 - INFO # IP Socket 6 : TCP, 0, 0, ap0: 5557, - , Listen
        2017-04-27 10:23:31,962 - INFO #
        2017-04-27 10:23:32,033 - INFO # IP Socket 7 : UDP, 0, 0,wlan0: 68, - , Listen
        2017-04-27 10:23:32,034 - INFO #
        2017-04-27 10:23:32,105 - INFO # IP Socket 8 : TCP, 0, 0,wlan0: 80, - , Listen
        2017-04-27 10:23:32,106 - INFO #
        2017-04-27 10:23:32,177 - INFO # IP Socket 9 : TCP, 0, 0,wlan0: 5555, - , Listen
        2017-04-27 10:23:32,178 - INFO #
        2017-04-27 10:23:32,249 - INFO # IP Socket 10: TCP, 0, 0,wlan0: 5556, - , Listen
        2017-04-27 10:23:32,250 - INFO #
        2017-04-27 10:23:32,320 - INFO # IP Socket 11: TCP, 0, 0,wlan0: 5557, - , Listen
        2017-04-27 10:23:32,322 - INFO #
        2017-04-27 10:23:32,392 - INFO # IP Socket 12: UDP, 0, 0, ap0:30718, - , Listen
        2017-04-27 10:23:32,393 - INFO #
        2017-04-27 10:23:32,464 - INFO # IP Socket 13: UDP, 0, 0,wlan0:30718, - , Listen
        2017-04-27 10:23:32,465 - INFO #
        2017-04-27 10:23:32,751 - INFO # status Diagnostics Threads>show
        2017-04-27 10:23:32,752 - INFO #
        2017-04-27 10:23:32,781 - INFO # Diagnostics Threads Status:
        2017-04-27 10:23:32,782 - INFO #
        2017-04-27 10:23:32,826 - INFO # Thread Interrupt : 39% Green
        2017-04-27 10:23:32,827 - INFO #
        2017-04-27 10:23:32,869 - INFO # Thread Watchdog : 73% Green
        2017-04-27 10:23:32,870 - INFO #
        2017-04-27 10:23:32,911 - INFO # Thread Shared Worker : 76% Green
        2017-04-27 10:23:32,912 - INFO #
        2017-04-27 10:23:32,954 - INFO # Thread Line 2 CLI : 52% Green
        2017-04-27 10:23:32,955 - INFO #
        2017-04-27 10:23:32,997 - INFO # Thread Connection Manager: 59% Green
        2017-04-27 10:23:32,998 - INFO #
        2017-04-27 10:23:33,040 - INFO # Thread Http1 : 5% Green
        2017-04-27 10:23:33,041 - INFO #
        2017-04-27 10:23:33,082 - INFO # Thread Http0 : 62% Green
        2017-04-27 10:23:33,083 - INFO #
        2017-04-27 10:23:33,125 - INFO # Thread SNTP : 51% Green
        2017-04-27 10:23:33,126 - INFO #
        2017-04-27 10:23:33,168 - INFO # Thread WICED : 73% Green
        2017-04-27 10:23:33,169 - INFO #
        2017-04-27 10:23:33,210 - INFO # Thread NetX ap0 IP : 14% Green
        2017-04-27 10:23:33,211 - INFO #
        2017-04-27 10:23:33,253 - INFO # Thread mux : 30% Green
        2017-04-27 10:23:33,254 - INFO #
        2017-04-27 10:23:33,296 - INFO # Thread NetX wlan0 IP : 43% Green
        2017-04-27 10:23:33,297 - INFO #
        2017-04-27 10:23:33,338 - INFO # Thread NetX AutoIP : 79% Green

        I'd love to try a new firmware, but whenever I confirm updating the firmware image and get "Rebooting device...", the device will reboot but instead of going to the OTA loader, it just boots it's normal firmware.

        Comment


        • #5
          no firmware update possible with RESET = HIGH

          I configured DEFAULT, EXT_RESET# and WKUP as output with PULLUP resistor on my STM32 - they are always HIGH during normal operation (and also when performing the firmware update).

          Is this wrong?

          I can perform the firmware update when I leave them unconfigured.

          (I will also see if I can reproduce the main issue with 1.5.0.0A25)

          Comment


          • #6
            Ok, firmware update works when I pull every pin to HIGH state right after init, I will now try to reproduce the issue with firmware 1.5.0.0A25.

            Comment


            • #7
              I managed to reproduce the issue with the latest firmware (1.5.0.0A25) now. Still nothing unusual in xPico logs, but the router log shows that the device disconnected at 04:48:20 and reconnects 05:34:33.

              For that period of time it was not reachable.

              Comment


              • #8
                I think found a temporary solution in running the diagnostic ping command (now works reliably in 1.5.0.0A25, it did not in 1.4) every 10 seconds to test if I can reach the default gateway.

                If that fails I run DHCP renew.

                It's not a very nice solution as it blocks the CLI interface and takes up another thread for the periodic pings.

                Comment

                Working...
                X