Fun with SEQ Log :-)

User avatar
W3MMR
Posts: 145
Joined: Thu Jul 11, 2019 8:36 am
Location: Springfield, PA
Contact:

Re: Fun with SEQ Log :-)

Postby W3MMR » Sat Nov 16, 2019 9:44 pm

I seem to be getting A LOT of seq errors. Nothing that you are looking for, just a random 1 in a sequence of 0's. But they happen at all times. Transmitting, receiving, doing other tasks, not doing other tasks, etc etc. Not causing any issues. No audio drop outs, no freeze ups, nothing besides the errors themselves. Not worried about it, just wanted to let it be known. Using a 200D, P2 v 1.8, a6_2.
Heres a snippet... They all look like this...

log.PNG
log.PNG (33.33 KiB) Viewed 12832 times


Perry
ea3aqr
Posts: 270
Joined: Mon Mar 04, 2019 10:50 pm
Location: BCN

Re: Fun with SEQ Log :-)

Postby ea3aqr » Tue Nov 19, 2019 11:52 pm

Anan 7000 DLE
Firmware P2 2.0 Pre1
Thetis v2.6.9 a8

Got lots of SEQ errors with this new build and most important, my first -ve SEQ errors:

DCC0
s0=0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 2 10 1 0 0 0 0 0 0 11/20 00:44:22:924
s1=0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 2 10 0 0 0 0 0 0 0 11/20 00:44:22:924
s2=0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 2 0 0 0 0 0 0 0 0 11/20 00:44:22:924
s3=0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1 8 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 11/20 00:44:22:858
s4=0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 11/20 00:44:22:858
s5=5 5 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 11/20 00:44:22:792
s6=5 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 11/20 00:44:22:792
s7=0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 8 2 0 0 0 0 0 0 0 0 0 0 0 0 0 11/20 00:44:22:727
s8=0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 8 0 0 0 0 0 0 0 0 0 0 0 0 0 0 11/20 00:44:22:727
s9=0 0 0 0 0 0 0 0 0 0 1 5 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 11/20 00:44:22:662
s10=0 0 0 0 0 0 0 0 0 0 1 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 11/20 00:44:22:662
s11=0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 8 10 0 0 0 0 0 0 0 0 0 0 0 0 0 0 11/20 00:39:46:438
s12=0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 8 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 11/20 00:39:46:438
s13=0 0 5852366 -5852367 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 11/20 00:38:41:780

DCC2
s0=0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 7 12 0 0 11/20 00:39:46:438
s1=0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 7 0 0 0 11/20 00:39:46:438

DCC0
s0=0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 8 10 0 0 0 0 0 0 0 0 0 0 0 0 0 0 11/20 00:39:46:438
s1=0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 8 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 11/20 00:39:46:438
s2=0 0 5852366 -5852367 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 11/20 00:38:41:780

DCC0
s0=0 0 5852366 -5852367 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 11/20 00:38:41:780
New call sign EA3CL
User avatar
ramdor
Posts: 1468
Joined: Wed Jul 03, 2019 3:07 pm
Contact:

Re: Fun with SEQ Log :-)

Postby ramdor » Wed Nov 20, 2019 2:08 am

s12=0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 8 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 11/20 00:39:46:438
s13=0 0 5852366 -5852367 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 11/20 00:38:41:780


The small numbers ok fine, but 5852366 -5852367 ?

Only thing I can think of is that the packet with delta of 5852366 was some random case of the packet being the correct length (1444 bytes) to pass the 'malformed packet check' but at a minimum the sequence number was corrupt. I am wondering now if these 'replay' events are just that the sequence number of a received packet is corrupt in some way.

I dont know the answer to the issue. As a start does anyone know if radio->pc udp packets have ip4 (optional) checksums calculated and included in the ip4 header?

Richie.
W4WMT
Posts: 325
Joined: Sun Apr 09, 2017 10:12 pm

Re: Fun with SEQ Log :-)

Postby W4WMT » Wed Nov 20, 2019 10:02 am

ramdor wrote:
Only thing I can think of is that the packet with delta of 5852366 was some random case of the packet being the correct length (1444 bytes) to pass the 'malformed packet check' but at a minimum the sequence number was corrupt. I am wondering now if these 'replay' events are just that the sequence number of a received packet is corrupt in some way.

I dont know the answer to the issue. As a start does anyone know if radio->pc udp packets have ip4 (optional) checksums calculated and included in the ip4 header?

Richie.


It would be nice if one of these were captured in Wireshark!

73
w9mdb
Posts: 446
Joined: Sun Apr 09, 2017 5:53 pm

Re: Fun with SEQ Log :-)

Postby w9mdb » Wed Nov 20, 2019 2:30 pm

Nope...checksum is always zero... at least on my ANAN 100 with the current Thetis firmware.

0x0000: 4500 05c0 7205 0000 8011 0000 c0a8 0164 E...r..........d
0x0000: 4500 05c0 7206 0000 8011 0000 c0a8 0164 E...r..........d
0x0000: 4500 05c0 7207 0000 8011 0000 c0a8 0164 E...r..........d
0x0000: 4500 05c0 7208 0000 8011 0000 c0a8 0164 E...r..........d
0x0000: 4500 05c0 7209 0000 8011 0000 c0a8 0164 E...r..........d
0x0000: 4500 05c0 720a 0000 8011 0000 c0a8 0164 E...r..........d
0x0000: 4500 05c0 720b 0000 8011 0000 c0a8 0164 E...r..........d
0x0000: 4500 05c0 720c 0000 8011 0000 c0a8 0164 E...r..........d
0x0000: 4500 05c0 720d 0000 8011 0000 c0a8 0164 E...r..........d
0x0000: 4500 05c0 720e 0000 8011 0000 c0a8 0164 E...r..........d
0x0000: 4500 05c0 720f 0000 8011 0000 c0a8 0164 E...r..........d
Mike W9MDB
User avatar
w-u-2-o
Posts: 5540
Joined: Fri Mar 10, 2017 1:47 pm

Re: Fun with SEQ Log :-)

Postby w-u-2-o » Wed Nov 20, 2019 3:05 pm

Bryan W4WMT wrote:
ramdor wrote:
Only thing I can think of is that the packet with delta of 5852366 was some random case of the packet being the correct length (1444 bytes) to pass the 'malformed packet check' but at a minimum the sequence number was corrupt. I am wondering now if these 'replay' events are just that the sequence number of a received packet is corrupt in some way.

I dont know the answer to the issue. As a start does anyone know if radio->pc udp packets have ip4 (optional) checksums calculated and included in the ip4 header?

Richie.


It would be nice if one of these were captured in Wireshark!

73

Here is a mechanism by which this could possibly be done:

https://osqa-ask.wireshark.org/questions/48119/stop-the-trace-from-external-event

Assuming the correct version of dumpcap (Wireshark) is installed, a minimal implementation would start dumpcap manually or from a script with appropriate ring buffer and other parameters, and then Thetis would be engineered to kill the dumpcap process on the appropriate trigger condition (seq log condition) by knowing the process name a priori. The resulting dumpcap logs could then be inspected in Wireshark and, assuming the ring buffer is of a reasonable size, it would only be a very small amount of data to search through to find the offending instance.

A more sophisticated implementation would see Thetis kicking off a fresh dumpcap process after each seq log event so that a number of events could be captured in an automated fashion.

73,

Scott
User avatar
ramdor
Posts: 1468
Joined: Wed Jul 03, 2019 3:07 pm
Contact:

Re: Fun with SEQ Log :-)

Postby ramdor » Wed Nov 20, 2019 6:45 pm

Yes Michael, it seems that the radio doesn't build packet checksums for the UDP payload.

Scott, I have added your wireshark idea in and is working well. Just need to add some UI so users can config wireshark folder etc if installed. Also to include sequence numbers as well as delta in the seq log window. Also some config stuff to only kill process on -ve delta, clear folder etc etc. etc.

Richie.
User avatar
w-u-2-o
Posts: 5540
Joined: Fri Mar 10, 2017 1:47 pm

Re: Fun with SEQ Log :-)

Postby w-u-2-o » Wed Nov 20, 2019 7:19 pm

Zowie! You are going to be drowning in data now! Like Ripley says, "It's the only way to be sure." :D
ea3aqr
Posts: 270
Joined: Mon Mar 04, 2019 10:50 pm
Location: BCN

Re: Fun with SEQ Log :-)

Postby ea3aqr » Wed Nov 20, 2019 9:52 pm

Another -ve SEQ error.

Today on Thetis 2.6.9 a8_1

DCC0
s0=0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 -17 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 11/20 22:51:01:414


EDIT:
After changing my sound card settings from 16Bits-96Khz to 24Bits-96Khz and tweaking a little bit my RingBuffer (3, 3) and PorAudio (0, 0) latencies, no more SEQ errors this evening and just a couple of packet drops in 1h of ragchew QSO.
New call sign EA3CL
User avatar
ramdor
Posts: 1468
Joined: Wed Jul 03, 2019 3:07 pm
Contact:

Re: Fun with SEQ Log :-)

Postby ramdor » Thu Nov 21, 2019 5:41 am

Ok during the testing of this dumpcap system I found something very interesting here.

Here, the 7000dleMk2 (pre4) just gives up sending packets for a while, for every single DHCP ACK broadcast UDP message that happens on the lan as part of the DHCP messaging. As there are something around 20-30 devices here (dont ask lol), and a bunch of VM's it happens somewhat often.

I have been plagued by packet loss from 1 packet up to a couple of hundred packets, seemingly random, and now I know what it is. Every single SEQ event when tracked through WireShark has an associated DHCP ACK message.

I'd be very interested if someone with a couple of PC's on the same lan as the radio (same subnet), using a DHCP server did some tests.

a) run Thetis on machine A, that has a dhcp ip address, and is using the radio that has a fixed IP address
b) renew lease on machine B that uses the DHCP server on same subnet as everything else, to obtain a new IP


It should be noted that when the 7kdle goes silent, the SunSDR2 Pro here does not, and seemingly ignores/handles those irrelevant DHCP broadcasts that reach it.

The packets that cause the issues are Boot Reply (2) DHCP ACK messages. Broadcast with mac address of ff:ff:ff:ff:ff:ff. We have tested a couple of different DHCP servers, all cause the same issue with the radio.

Richie.
W4WMT
Posts: 325
Joined: Sun Apr 09, 2017 10:12 pm

Re: Fun with SEQ Log :-)

Postby W4WMT » Thu Nov 21, 2019 10:08 am

ramdor wrote:
I'd be very interested if someone with a couple of PC's on the same lan as the radio (same subnet), using a DHCP server did some tests.

a) run Thetis on machine A, that has a dhcp ip address, and is using the radio that has a fixed IP address
b) renew lease on machine B that uses the DHCP server on same subnet as everything else, to obtain a new IP

Richie.



Hi Richie,

Yes, I can replicate here, sort of:
My 7000DLE is using dhcp, not static ip.
My Windows 7 "machine B" causes packet loss each time I /release /renew its dhcp ip address using ipconfig.
My Windows 10 "machine B" does not cause the effect.
My Windows XP (don't ask :lol: ) "machine B" does not cause the effect.

I wonder why the inconsistent results?

73
User avatar
ramdor
Posts: 1468
Joined: Wed Jul 03, 2019 3:07 pm
Contact:

Re: Fun with SEQ Log :-)

Postby ramdor » Thu Nov 21, 2019 1:41 pm

No idea, I started to investigate how to get a dev environment up and running for the firmware last night, then I slapped myself out of the bad dream.

Joking aside, it does need looking at for this alone. Short term solution is to vlan the radio or put it behind a router to filter port 67/68 traffic before it hits the anan. Has to be struggling to deal with this packet somehow.

Richie.
W4WMT
Posts: 325
Joined: Sun Apr 09, 2017 10:12 pm

Re: Fun with SEQ Log :-)

Postby W4WMT » Thu Nov 21, 2019 2:08 pm

ramdor wrote:Joking aside, it does need looking at for this alone. Short term solution is to vlan the radio or put it behind a router to filter port 67/68 traffic before it hits the anan. Has to be struggling to deal with this packet somehow.

Richie.


What about users who are connecting their radios directly to the PC's nic? They appear to be seeing dropped packets also. But their radios should be protected from the dhcp deathpacket, no?

73
User avatar
ramdor
Posts: 1468
Joined: Wed Jul 03, 2019 3:07 pm
Contact:

Re: Fun with SEQ Log :-)

Postby ramdor » Thu Nov 21, 2019 2:34 pm

I don't know enough about the low levels of windows networking really Bryan to say. I dont know that if those dhcp packets arrive on one nic if they get piped out over the other, i would need to setup a testbed here. This machine has two intel mobo based nics so it is something I can test.

Even though the dhcp server is on 255.255.255.0 192.168.0.x network I get the dhcp spam on 255.255.255.0 192.168.10.x, and after reading up on it is caused by the switches here dealing with the ff;ff;ff;ff addressed message and slapping it out all ports on the switch and even swapping out any mac address for a bunch of ff's.

I have had it happen since I had the radio, and just lived with it. However, after correlating every single SEQ problem i get here and to see that one or two packets after the last good thetis udp 1444 byte frame there is one of these dhcp ack's then it was a case of 2+2.

Then to take that info and get my phone to release/renew and see the radio fail, then to try it on other computers, then to switch from sbs2011 dhcp server to a couple of others and see the same problem. You can even use dhcploc.exe from technet, run it up with your interface's IP, and mash D on any computer on the network and have SEQ messages on other machines. Not good really :/

Richie.
User avatar
w-u-2-o
Posts: 5540
Joined: Fri Mar 10, 2017 1:47 pm

Re: Fun with SEQ Log :-)

Postby w-u-2-o » Thu Nov 21, 2019 2:49 pm

This seems like a very minor problem. DHCP ack broadcasts should be relatively rare, even on a well populated LAN. Not saying it shouldn't be fixed, of course.

I mostly get seq errors when I apparently oversubscribe the critical threads (get the red box). This could be proven by showing that all packets are there at the NIC but somehow not received by Thetis.
w9mdb
Posts: 446
Joined: Sun Apr 09, 2017 5:53 pm

Re: Fun with SEQ Log :-)

Postby w9mdb » Thu Nov 21, 2019 2:52 pm

What red box?
Mike W9MDB
User avatar
ramdor
Posts: 1468
Joined: Wed Jul 03, 2019 3:07 pm
Contact:

Re: Fun with SEQ Log :-)

Postby ramdor » Thu Nov 21, 2019 2:59 pm

w-u-2-o wrote:This seems like a very minor problem. DHCP ack broadcasts should be relatively rare, even on a well populated LAN. Not saying it shouldn't be fixed, of course.

I mostly get seq errors when I apparently oversubscribe the critical threads (get the red box). This could be proven by showing that all packets are there at the NIC but somehow not received by Thetis.


I have lived with it, but it is a problem here, as we have legacy gear that needs to be running and seemingly ignores lease time. That gear sleeps quite often and when it wakes up, well it keeps the dhcp server busy.

I can run the system in GDI+ with the red box shown all the time and see no seq errors, 60fps specified, mid 30's being achieved. Each and every system is different in that regard it seems, but the radio having a hickup because a dhcp broadcast packet arrives is pretty bad imo.

Richie.
User avatar
ramdor
Posts: 1468
Joined: Wed Jul 03, 2019 3:07 pm
Contact:

Re: Fun with SEQ Log :-)

Postby ramdor » Thu Nov 21, 2019 3:00 pm

w9mdb wrote:What red box?


:D :lol: - I laugh jokingly of course, because if you haven't seen it your system is working great !

Untitled.png
Untitled.png (4.42 KiB) Viewed 12623 times


It will only be shown if the desired fps (configured in setup) is not being achieved. If you run GDI+ then this will impact pretty much all the UI, and slow it down due to the way the paint event is still being processed in the main UI thread, although the refresh was called from a different thread.

If you see the red box in DirectX mode the UI wont be impacted.

Impacting the UI thread and potentially causing it to be 'locked' is not ideal, neither are the Thread.Sleep's related to rf/mox/rx delay either, but they are left as they are atm.

Richie.
User avatar
ramdor
Posts: 1468
Joined: Wed Jul 03, 2019 3:07 pm
Contact:

Re: Fun with SEQ Log :-)

Postby ramdor » Thu Nov 21, 2019 11:59 pm

If you fancy capturing some network data, and use the L (last seq number) field in the seq log to use as a search into the dumpcap logs, then.... viewtopic.php?f=9&p=9185#p9183

Richie.
User avatar
W3MMR
Posts: 145
Joined: Thu Jul 11, 2019 8:36 am
Location: Springfield, PA
Contact:

Re: Fun with SEQ Log :-)

Postby W3MMR » Fri Nov 22, 2019 2:04 am

So, newbie question. Does a random "1" in a sequence of zeros mean a single packet is lost? I get a ton of seq error's but they are ALWAYS a random 1 in a sequence of 0's. Is this anything to be worried about or is there a way to combat this? Or should I just not worry about it?
loggg.PNG
loggg.PNG (38.1 KiB) Viewed 12589 times

Thanks
Perry
User avatar
ramdor
Posts: 1468
Joined: Wed Jul 03, 2019 3:07 pm
Contact:

Re: Fun with SEQ Log :-)

Postby ramdor » Fri Nov 22, 2019 2:14 am

yes, the last entry on the ddc2 s0=... the top line as a 1 on the right hand side, that would be the packet that was out of sequence, ie 1 greater than expected. If you look at r: that is the received sequence number, which if you look is 2 greater than l: which is the last packet number. 2 greater than last or 1 greater than expected.

So, they are a couple of mins apart, s0,s1,s2 etc, 1 packet every so often is lost, not much to worry about really. You could enable the wireshark stuff, and use in the case of s0 the l:12732186 packet sequnece number, convert it to hex and do a search through the dumpcap files. Then look to see if anything is happening on the lan/whatnot at the time of the packet loss. You might not even see anything, but you will see udp packets with 1444 bytes, counting up with 1 missing.

If I get a mo, over the weekend, I might make a vid on how to use the info so people can try track down what is going on.

Richie.

Return to “Thetis”