Pistar loses connection to P25 Reflector...

Help with P25 issues
KK6RQ
Posts: 13
Joined: Mon Feb 22, 2021 9:32 am

Pistar loses connection to P25 Reflector...

Post by KK6RQ »

(BTW, this is also posted over on groups.io; dunno if that's a problem; if it is, I'll gladly refrain)


Hope someone recognizes what's going on because I'm stumped at this point. I'm running a duplex Pi-star, P25-only, as well as another Pi on the same subnet w/ DVSwitch DMR-P25 bridge + P25Reflector. Everything works fine, I talk to my friends, etc., etc., but then randomly, sometimes minutes, sometimes days after boot, the pistar P25 is suddenly unable to properly access the P25 reflector. The error I get in /var/log/pi-star/MMDVM-[date].log is:

M: 2021-02-21 00:34:16.566 P25 packet received from an invalid source, 0100007F != 0100007F and/or 42020 != 6074.

The reflector continues to kick back my last syllable like normal but it doesn't make it out the network, nor can I switch to another reflector. A reboot always cures the problem (until the next time, of course). The reflector and the bridge continue to function for everyone else, btw. Anybody recognize this error or what might be happening here? Thanks.

ps. Other (outside) users are still able to use the reflector/DMR bridge.
KE7FNS
Pi-Star Team
Posts: 1794
Joined: Wed Apr 17, 2019 11:11 pm

Re: Pistar loses connection to P25 Reflector...

Post by KE7FNS »

KK6RQ wrote: Tue Feb 23, 2021 5:46 am M: 2021-02-21 00:34:16.566 P25 packet received from an invalid source, 0100007F != 0100007F and/or 42020 != 6074.
Thats interesting.

I took a look at the source code and its complaining that the ports don't match.

Code: Select all

	// Check if the data is for us
	if (m_address.s_addr != address.s_addr || m_port != port) {
		LogMessage("P25 packet received from an invalid source, %08X != %08X and/or %u != %u", m_address.s_addr, address.s_addr, m_port, port);
		return;
	}
As you can see, m_port is 42020 and port is 6074, and they don't match.

What makes things even worse is this file (P25Network.cpp) has been been updated a few times over the last year, and Andy is running old code.

The new code doesn't even bother to check the ports anymore, so maybe someone realized this was a problem.

Code: Select all

	if (!CUDPSocket::match(m_addr, address)) {
		LogMessage("P25, packet received from an invalid source");
		return;
	}
Maybe Andy will update MMDVMHost, I know I would like it since ON7LDS added a new feature for Nextions a few months ago.
If someones previous actions are any indication of their future actions, then I predict the deletion and removal of access will happen at any moment. 7-11-2020.

"07/13/20 This Website Has Been Taken Down" ... again :lol:
KK6RQ
Posts: 13
Joined: Mon Feb 22, 2021 9:32 am

Re: Pistar loses connection to P25 Reflector...

Post by KK6RQ »

Additional error messages I just noticed--

MMDVM-[date].log:
Network watchdog has expired 1.6 seconds, 0% packet loss

P25Gateway-[date].log: Error returned from recvfrom, err: 88
Re-opening UDP port on 339628
Opening UDP port on 6074

ps. I never knew ports went that high (ie. 6 figures).
KE7FNS
Pi-Star Team
Posts: 1794
Joined: Wed Apr 17, 2019 11:11 pm

Re: Pistar loses connection to P25 Reflector...

Post by KE7FNS »

KK6RQ wrote: Sun Feb 28, 2021 2:15 am ps. I never knew ports went that high (ie. 6 figures).
Yeah, they don't.

It supposed to be an unsigned short, max value is 65535 (0xffff). No idea where that number is coming from.
If someones previous actions are any indication of their future actions, then I predict the deletion and removal of access will happen at any moment. 7-11-2020.

"07/13/20 This Website Has Been Taken Down" ... again :lol:
KK6RQ
Posts: 13
Joined: Mon Feb 22, 2021 9:32 am

Re: Pistar loses connection to P25 Reflector...

Post by KK6RQ »

More clues emerge...

So apparently my perception of the 'when' wasn't as exact as I thought... It now looks like the problem happens 6 hours before midnight (my time, CST), when the log files roll over. Pistar seems to timestamp entries in the log files in GMT, whereas the files themselves are timestamped w/local time. As soon as the new file is created, bang!...I'm disconnected from my reflector/any reflector. If it's of any consequence, for the next 6 hours there's 2 sequential log files, then the older one disappears at midnight. Hope this makes a lightbulb go on in *someone's* head...
User avatar
G8SEZ
Posts: 427
Joined: Fri Apr 13, 2018 8:26 pm

Re: Pistar loses connection to P25 Reflector...

Post by G8SEZ »

Do you maybe have a wrong time zone set up in your config? Looks like something sees a sudden change of apparent time and then falls over.
--

Brian G8SEZ
KE7FNS
Pi-Star Team
Posts: 1794
Joined: Wed Apr 17, 2019 11:11 pm

Re: Pistar loses connection to P25 Reflector...

Post by KE7FNS »

KK6RQ wrote: Tue Mar 02, 2021 11:02 pm So apparently my perception of the 'when' wasn't as exact as I thought... It now looks like the problem happens 6 hours before midnight (my time, CST), when the log files roll over. Pistar seems to timestamp entries in the log files in GMT, whereas the files themselves are timestamped w/local time. As soon as the new file is created, bang!...I'm disconnected from my reflector/any reflector. If it's of any consequence, for the next 6 hours there's 2 sequential log files, then the older one disappears at midnight. Hope this makes a lightbulb go on in *someone's* head...
It doesn't appear to have anything to do with the timestamps, plus a file is always going to use the OS's locale to display when a file was created or modified.

Code: Select all

void CP25Control::clock(unsigned int ms)
{
	if (m_network != NULL)
		writeNetwork();

	m_rfTimeout.clock(ms);
	m_netTimeout.clock(ms);

	if (m_netState == RS_NET_AUDIO) {
		m_networkWatchdog.clock(ms);

		if (m_networkWatchdog.hasExpired()) {
			LogMessage("P25, network watchdog has expired, %.1f seconds, %u%% packet loss", float(m_netFrames) / 50.0F, (m_netLost * 100U) / m_netFrames);
			m_display->clearP25();
			m_networkWatchdog.stop();
			m_netState = RS_NET_IDLE;
			m_netData.reset();
			m_netTimeout.stop();
		}
	}
}
What seems to be happening is m_networkWatchdog.hasExpired() returns true, and it returns its network state to idle. So it is doing what it is programmed to do.

The question is though is the time change from one day to the next causing it to be expired when it shouldn't and I don't think that is the case since the timer is so basic.

Code: Select all

	bool hasExpired()
	{
		if (m_timeout == 0U || m_timer == 0U)
			return false;

		if (m_timer >= m_timeout)
			return true;

		return false;
	}
m_timer seems to just be incremented by 1 every time clock is called.

Code: Select all

	void clock(unsigned int ticks = 1U)
	{
		if (m_timer > 0U && m_timeout > 0U)
			m_timer += ticks;
	}
Maybe there is a cron job, or another watchdog that shuts down the services and restarts them. I know that happens during updating.
If someones previous actions are any indication of their future actions, then I predict the deletion and removal of access will happen at any moment. 7-11-2020.

"07/13/20 This Website Has Been Taken Down" ... again :lol:
KK6RQ
Posts: 13
Joined: Mon Feb 22, 2021 9:32 am

Re: Pistar loses connection to P25 Reflector...

Post by KK6RQ »

Would it help if I posted something...? (Cron admin is not my strong suit). Let me know...

Timezone question: No, it's correct; 1st thing I checked.
KE7FNS
Pi-Star Team
Posts: 1794
Joined: Wed Apr 17, 2019 11:11 pm

Re: Pistar loses connection to P25 Reflector...

Post by KE7FNS »

KK6RQ wrote: Wed Mar 03, 2021 2:39 am Would it help if I posted something...? (Cron admin is not my strong suit). Let me know...
Well I don't see any crons that run right at 0:00, so it might be a service or watchdog timer getting stopped and restarted.

Since you know the time it fails, capture the last few minutes of the log and up until the failure and see if you can figure out what is causing it to timeout.
If someones previous actions are any indication of their future actions, then I predict the deletion and removal of access will happen at any moment. 7-11-2020.

"07/13/20 This Website Has Been Taken Down" ... again :lol:
KK6RQ
Posts: 13
Joined: Mon Feb 22, 2021 9:32 am

Re: Pistar loses connection to P25 Reflector...

Post by KK6RQ »

Nothing beyond what I've already posted shows in MMDVM/P25Gateway-(date).log. Any other log files I should check?

One thing that changes each night is the number after

Re-opening UDP port on xxxxxxx

Last night it was 7 digits!
Post Reply