Switch Module Broken

[jhughesoti]

Recently started encountering a full failure of the switch module. Not entirely sure at what commit this started but it's something recent. Here is the activate.log being used. The one thing that jumps for me is that it shows

Switch test with ip:port 192.168.100.99:2

But the config is port 24. I had this originally at port 12 and noticed it was always at 1. I swapped it to see if it had similar issues with double digit ports and i'm not sure if this is a logging failure or a real failure to use the correct port.

PING 10.20.0.1 (10.20.0.1) 56(84) bytes of data.
64 bytes from 10.20.0.1: icmp_seq=1 ttl=64 time=1.88 ms
64 bytes from 10.20.0.1: icmp_seq=2 ttl=64 time=0.105 ms

--- 10.20.0.1 ping statistics ---
2 packets transmitted, 2 received, 0% packet loss, time 1001ms
rtt min/avg/max/mdev = 0.105/0.994/1.884/0.890 ms
Configuring network with local address 192.168.100.22/24.
Switch test with model CISCO_9300
Switch test with ip:port 192.168.100.99:2
PING 192.168.100.99 (192.168.100.99) 56(84) bytes of data.
64 bytes from 192.168.100.99: icmp_seq=1 ttl=255 time=2.09 ms
64 bytes from 192.168.100.99: icmp_seq=2 ttl=255 time=0.823 ms
64 bytes from 192.168.100.99: icmp_seq=3 ttl=255 time=0.749 ms
64 bytes from 192.168.100.99: icmp_seq=4 ttl=255 time=0.822 ms
64 bytes from 192.168.100.99: icmp_seq=5 ttl=255 time=0.785 ms
64 bytes from 192.168.100.99: icmp_seq=6 ttl=255 time=0.814 ms
64 bytes from 192.168.100.99: icmp_seq=7 ttl=255 time=0.750 ms
64 bytes from 192.168.100.99: icmp_seq=8 ttl=255 time=0.742 ms
64 bytes from 192.168.100.99: icmp_seq=9 ttl=255 time=0.813 ms
64 bytes from 192.168.100.99: icmp_seq=10 ttl=255 time=0.838 ms

--- 192.168.100.99 ping statistics ---
10 packets transmitted, 10 received, 0% packet loss, time 9202ms
rtt min/avg/max/mdev = 0.742/0.923/2.094/0.391 ms
Exception in thread "main" io.grpc.StatusRuntimeException: DEADLINE_EXCEEDED: deadline exceeded after 9.996601354s. [remote_addr=172.17.0.1/172.17.0.1:5000]
        at io.grpc.stub.ClientCalls.toStatusRuntimeException(ClientCalls.java:262)
        at io.grpc.stub.ClientCalls.getUnchecked(ClientCalls.java:243)
        at io.grpc.stub.ClientCalls.blockingUnaryCall(ClientCalls.java:156)
        at grpc.USIServiceGrpc$USIServiceBlockingStub.getInterface(USIServiceGrpc.java:335)
        at switchtest.SwitchTest.test(SwitchTest.java:164)
        at switchtest.Main.main(Main.java:45)

[jhughesoti]

After a bit more testing, that port appears to identify the port under test as I was testing a device on port 4 and noticed the number now matched that port. Either way, switch testing module still seems to be broken. Seems to be associated with the usi module creation and/or an update within it because this was not an issue before the update.

[noursaidi]

@jhughesbiot Just posting to mention that I'm using an Allied Telesis x230 and do not appear to have encountered any issues in the latest updates. Tagging @pisuke to check with his Cisco set up too.

[henry54809]

@jhughesbiot Hi Jonathan, would you please try my branch at https://github.com/henry54809/daq/tree/feature/convert-switchtests. There was some additional output on the Cisco switch that caused a parsing error when getting interface information. I can directly access the logs for usi, so there is no need to send the logs. Thanks!

[jhughesoti]

@henry54809
I just cloned you're branch, built and ran a test with the same error.

[jhughesoti]

Another attempt i was going for before trying that branch was to downgrade to 1.8.2 but there seems to be some dependencies that don't let you downgrade and it complains about rerunning the setup_dev, which makes no difference to the error.

[jhughesoti]

Probably would be helpful to show what i'm talking about:

Local udmi commit is at: b7ba8b039cbc6f70ba3831ca305a1685235c6087
Mismatch with etc/UDMI_VERSION: 1.0.0
Try bin/setup_dev to update.

[henry54809]

@jhughesbiot , did you rebuild images before running the test again? It's still showing the same line number that the error occurred but on the new branch, the line is a comment.

[jhughesoti]

I rebuilt with the same exact error. On examining the code of that branch, it has the following has which shows no comment on that line. Maybe it's not pushed?

LIne 164
.withDeadlineAfter(rpcTimeoutSec, TimeUnit.SECONDS).getInterface(switchInfo);

https://github.com/henry54809/daq/blob/feature/convert-switchtests/subset/switches/src/main/java/switchtest/SwitchTest.java

  /**
   * Run a switch test with the specified switch info.
   * @param switchInfo SwitchInfo from the USI proto file
   */
  public void test(SwitchInfo switchInfo) {
    final PowerResponse powerResponse = blockingStub
        .withDeadlineAfter(rpcTimeoutSec, TimeUnit.SECONDS).getPower(switchInfo);
    final InterfaceResponse interfaceResponse = blockingStub
        .withDeadlineAfter(rpcTimeoutSec, TimeUnit.SECONDS).getInterface(switchInfo);
    testLink(interfaceResponse);
    testSpeed(interfaceResponse);
    testDuplex(interfaceResponse);
    testPower(powerResponse);
    writeReport();
  }
}

[henry54809]

@jhughesbiot, oh I was actually referring to the code for USI. The logs from 17:13 PDT run is showing that the java string index of out of bounds exception (in USI) was occurring on daq.usi.BaseSwitchController.mapSimpleTable on line 81 which is a comment in the new branch. Switch test stays the same since the parsing logic is only in USI .

[jhughesoti]

I did rebuild before I ran but i'll try again to see if anything changes. Not sure what logs you're referring to or how I check them concerning the usi module, haven't seen where those exist.

[jhughesoti]

Good news! Rebuilt everything and the full switch failure goes away. Not sure why it didn't behave that way last time, I didn't do anything different this time around.

The bad news is that there's still something broken in the cisco side of things. I was originally testing on a new device and was seeing failures across the board with this branch so I swapped to a known good device and it also now has all failure results. There also seems to be a complete loss of any logging in the activate.log for the switch module which used to show all the raw switch results. I haven't really dug into the usi module rewrite of this section of the testing but there's definitely some issues on the Cisco side of things.

[henry54809]

The switch test was rewritten to use USI which should give more stable and accurate results. The full switch telnet logs are still available but are in usi container. After every run, the usi log is copied to inst directory under cmdusi.log. That log is also streamed directly to stackdriver so I can see the logs live.

[jhughesoti]

I see that log now but i think there's an oversight here on the switch module during that migration because now the switch module is completely removed from any ability to determine failure/success causes in it's reporting and there's nothing it captures to allow for logging of any issues during the switch level tests. Makes it very difficult to report any issues contained to the switch within that module. This feel like an important ability that the switch module is capable of knowing what happened during the test, not just the results.

Regardless of my opinions on that topic, the migration seems to have introduced failures on cisco because the usi log shows all the correct statuses but returns failure results now in addition to it being fully failed right now outside your branch.

[henry54809]

@jhughesbiot, the objective of the USI is to Standardize switch responses so we can remove switch specific information from everywhere else. If there’s some unexpected telnet output, USI is going to respond with an empty response which switch test will use to fail the test; this is likely why you’re seeing a test failure. If not, then there’s some difference in switch test logic.

[jhughesoti]

@henry54809
I understand the need to standardize the switch logic but my point to the usi is that this breaks all expectations of what every other test module is responsible for. All other tests have control over the environment and logging allowing for proper reporting to the final report within that module. With the introduction of the usi module, the switch module can create no meaningful logs about what actually happened during the switch test. All it knows is that it either passes or it fails but can generate nothing in it's logging or report section about why. To me, that doesn't seem like a good implementation when the testing module has no idea what happened during the actual test because it happened in a different module.

The logs from the last run should be available to you for review so you can see it is not the response of the switch via the telnet logs but something else in the usi module that is no longer properly handling responses. From the output, it appears that something may have been trying to over-normalize the two switches as the issue seems to report the code now expecting an int and not accounting for the a- syntax. Possibly other areas having this removed during the migration, I haven't fully done a review of all the usi changes so that's just a guess based on the log.

Port      Name               Status       Vlan       Duplex  Speed Type
Gi1/0/4                      connected    trunk      a-full  a-100 10/100/1000BaseTX
daq#
Could not parse int for interface speed:
Sent response in getInterface