search

sm0svx / svxlink

Advanced repeater system software with EchoLink support for Linux including a GUI, Qtel - the Qt EchoLink client
http://svxlink.org/
Other
433 stars 170 forks source link

Lock-up into permanent transmit - Evidence points to MetarInformation #117

Closed f5vmr closed 9 years ago

f5vmr commented 9 years ago

For three mornings (out of 5 so far) I have found our repeater in permanent transmit with no access possible. However I was able to access the rPI software at distance and facilitate a reboot which was uneventful, and the repeater returned to normal service.

In reading the log for the ocurrences creating the stuck transmission, I found that a night-owl has been accessing the MetarInformation module, and had issued a "#" either 2 or three times, after each occasion the log ceases as the time it happened. If nothing else it has given the amplifier on our repeater a good soak test. What I cannot determine is the actual length of the tone this person used. DTMF muting is set ON.

So for the moment I have excluded ModuleMetarInformation from the running schedule until we resolve this issue.

The raspberry is using GPIO for COS and PTT and those signals are being passed to an ARS Echolink interface module, so everything is properly isolated. The whole unit has been running in my workshop four 4 weeks on a UHF repeater into a dummy load, and has not experienced this problem before.

However i noticed that in a couple of instances, not associated with the problem in the header that an error report had been generated "pthread_mutex_destroy:error 16" & "error 10". Whether this has an impact on the transmit problem or not I cannot imagine.

f5vmr commented 9 years ago

Another user in my group F1IGY reports the same thing on his installation, shut off after two "#" in two adjacent lines while in MetarInformation. He also notes in the log a few lines before the run-time termination is the line thread_mutex_destroy error 16. He is running his svxlink in SimplexLogic.

I add that the rPI is still active after the termination, it's just svxlink that stops.

Since removal of the ModuleMetarInformation from the Logic option our repeater has not failed.

sm0svx commented 9 years ago

Thanks for reporting!

Next time that happens, find out what PID (process ID) your SvxLink is running as and use the 'strace' utility to find out in what system call the application is blocking.

pidof svxlink
strace -p PID_printed_above

Even better if you have the possibility to run SvxLink under GDB (the GNU Debugger). When it stops, press Ctrl+C and use the "bt" command to get a backtrace. Post this backtrace here.

gdb /path/to/svxlink
gdb> run --whatever_svxlink_arguments_you_need
Ctrl+C
gdb> bt
sm0svx commented 9 years ago

To get the most helpful gdb printout SvxLink need to be compiled in debug mode:

cmake -DCMAKE_BUILD_TYPE=Debug ..
make

If your computer cannot handle the increased load, try compiling both in debug mode and with optimizations:

cmake -DCMAKE_BUILD_TYPE=RelWithDebInfo ..
make
dl1hrc commented 9 years ago

Hi I've tryed to simulate this here for more than twenty times but came not to the same result. Can you post the complete log when this problem has been encountered?

f5vmr commented 9 years ago

Hi Adi,

I think it is a Raspberry Model B problem - as we have in our installation, as a friend has been unable to replicate the situation in the model B+. I have for the time being simply removed the module from use. I may replace the rPI with a B+ ultimately.

As for the svxlink.log, there is nothing out of the ordinary in the log other than what you would expect "squelch open Tx On CTCSS tone received, DTMF Tone "#" etc." Hence the supposition of it being a rPI type issue. I mentioned the pthread_mutex error, but that has not been seen again since I excluded the module.

Attached are three three logs for the three occurrences over four nights. There was no failure on the other night as no one accessed the metarinformation module.

Regards

Chris F5VMR 00:32: Rx1: The squelch is OPEN (3.7652) 00:32: RepeaterLogic: digit=0 00:32: DTMF digit received in module MetarInfo: 0 00:32: RepeaterLogic: digit=# 00:32: DTMF digit received in module MetarInfo: # 00:32: Rx1: The squelch is CLOSED (-2.33063) 00:32: DTMF command received in module MetarInfo: 0 00:32: say metarhelp 00:32: * WARNING: Could not find audio clip "metarhelp" in context "MetarInfo" 00:32: Rx1: The squelch is OPEN (27.974) 00:32: RepeaterLogic: digit=2 00:32: DTMF digit received in module MetarInfo: 2 00:32: RepeaterLogic: digit=# 00:32: DTMF digit received in module MetarInfo: # 00:32: Rx1: The squelch is CLOSED (-1.47629) 00:32: DTMF command received in module MetarInfo: 2 00:32: airports LFBI 00:32: METAR: LFBI 112300Z AUTO 17007KT 9999 NSC 10/07 Q0998 00:32: metreport_time 2300 00:32: wind 170 07 unit_kts 00:32: visibility more_than 10 unit_kms 00:32: say nsc 00:32: temperature 10 00:32: dewpoint 7 00:32: qnh 998 00:33: Rx1: The squelch is OPEN (30.0398) 00:33: RepeaterLogic: digit=3 00:33: DTMF digit received in module MetarInfo: 3 00:33: RepeaterLogic: digit=# 00:33: DTMF digit received in module MetarInfo: # 00:33: Rx1: The squelch is CLOSED (0.968608) 00:33: DTMF command received in module MetarInfo: 3 00:33: airports LFBE 00:33: METAR: LFBE 112300Z AUTO 21008KT 190V250 9999 -RA BKN045/// BKN056/// OVC066/// ///TCU 12/09 Q1001 00:33: metreport_time 2300 00:33: wind 210 08 unit_kts 00:33: windvaries 190 250 00:33: visibility more_than 10 unit_kms 00:33: actualWX light ra 00:33: clouds bkn 4500 00:33: clouds bkn 5600 00:33: clouds ovc 6600 00:33: temperature 12 00:33: dewpoint 9 00:33: qnh 1001 00:34: Rx1: The squelch is OPEN (30.1504) 00:34: RepeaterLogic: digit=5 00:34: DTMF digit received in module MetarInfo: 5 00:34: RepeaterLogic: digit=5 00:34: DTMF digit received in module MetarInfo: 5 00:34: RepeaterLogic: digit=# 00:34: DTMF digit received in module MetarInfo: # 00:34: RepeaterLogic: digit=# 00:34: DTMF digit received in module MetarInfo: # 00:34: Rx1: The squelch is CLOSED (-2.41292) 00:34: DTMF command received in module MetarInfo: 55 00:34: icao-code by dtmf-method: LFBE 00:34: DTMF command received in module MetarInfo: 00:34: RepeaterLogic: Deactivating module MetarInfo... 00:34: pthread_mutex_destroy: error 10 00:34: Rx1: The squelch is OPEN (28.0751) 00:34: RepeaterLogic: digit=* 00:34: RepeaterLogic: digit=5 00:34: RepeaterLogic: digit=5 00:34: RepeaterLogic: digit=# 00:34: Rx1: The squelch is CLOSED (0.269972) 00:34: dtmfCmdReceivedWhenIdle 00:34: DTMF command received in module MetarInfo: 5 00:34: Rx1: The squelch is OPEN (29.5185) 00:34: RepeaterLogic: digit=# 00:34: Rx1: The squelch is CLOSED (-0.742529) 00:34: Rx1: The squelch is OPEN (28.8882) 00:34: RepeaterLogic: digit=5 00:34: RepeaterLogic: digit=# 00:34: Rx1: The squelch is CLOSED (-2.07735) 00:34: RepeaterLogic: Activating module MetarInfo... 00:34: Rx1: The squelch is OPEN (30.7793) 00:34: RepeaterLogic: digit=5 00:34: DTMF digit received in module MetarInfo: 5 00:34: RepeaterLogic: digit=# 00:34: DTMF digit received in module MetarInfo: # 00:34: Rx1: The squelch is CLOSED (-1.80252) 00:34: DTMF command received in module MetarInfo: 5 00:35: Rx1: The squelch is OPEN (29.662) 00:35: RepeaterLogic: digit=5 00:35: DTMF digit received in module MetarInfo: 5 00:35: RepeaterLogic: digit=# 00:35: DTMF digit received in module MetarInfo: # 00:35: Rx1: The squelch is CLOSED (-0.791416) 00:35: DTMF command received in module MetarInfo: 5 00:35: Rx1: The squelch is OPEN (28.728) 00:35: RepeaterLogic: digit=6 00:35: DTMF digit received in module MetarInfo: 6 00:35: RepeaterLogic: digit=# 00:35: DTMF digit received in module MetarInfo: # 00:35: Rx1: The squelch is CLOSED (-0.60571) 00:35: DTMF command received in module MetarInfo: 6 00:35: Rx1: The squelch is OPEN (28.0203) 00:35: RepeaterLogic: digit=5 00:35: DTMF digit received in module MetarInfo: 5 00:35: RepeaterLogic: digit=# 00:35: DTMF digit received in module MetarInfo: # 00:35: Rx1: The squelch is CLOSED (-0.734162) 00:35: DTMF command received in module MetarInfo: 5 00:35: Rx1: The squelch is OPEN (27.3217) 00:35: RepeaterLogic: 88 Hz tone call detected 00:35: RepeaterLogic: digit=# 00:35: RepeaterLogic: Ignoring DTMF digit "#" since the repeater is not up 00:35: Rx1: The squelch is CLOSED (29.3371) 00:35: Rx1: The squelch is OPEN (32.3698) 00:36: RepeaterLogic: digit=# 00:36: DTMF digit received in module MetarInfo: # 11:44: SvxLink v1.4.99.2 (Oct 31 2014) Copyright (C) 2003-2014 Tobias Blomberg / SM0SVX 11:44: 11:44: SvxLink comes with ABSOLUTELY NO WARRANTY. This is free software, and you are 11:44: welcome to redistribute it in accordance with the terms and conditions in the 11:44: GNU GPL (General Public License) version 2 or later. 11:44: 11:44: Using configuration file: /etc/svxlink/svxlink.conf 11:44: --- Using sample rate 48000Hz 22:34: Rx1: The squelch is CLOSED (22.2331) 22:34: Tx1: Turning the transmitter ON 22:34: RepeaterLogic: Nagging user about identifying himself 22:34: Rx1: The squelch is OPEN (7.75071) 22:34: RepeaterLogic: digit=5 22:34: RepeaterLogic: digit=# 22:34: RepeaterLogic: digit=# 22:34: Rx1: The squelch is CLOSED (0.98448) 22:34: RepeaterLogic: Activating module MetarInfo... 22:34: DTMF command received in module MetarInfo: 22:34: RepeaterLogic: Deactivating module MetarInfo... 22:34: pthread_mutex_destroy: error 10 22:35: Rx1: The squelch is OPEN (16.0971) 22:35: Rx1: The squelch is CLOSED (-0.0860189) 22:35: Rx1: The squelch is OPEN (8.8179) 22:35: RepeaterLogic: digit=5 22:35: RepeaterLogic: digit=# 22:35: Rx1: The squelch is CLOSED (-2.2743) 22:35: RepeaterLogic: Activating module MetarInfo... 22:35: Rx1: The squelch is OPEN (2.27596) 22:35: Rx1: The squelch is CLOSED (0.915558) 22:35: Rx1: The squelch is OPEN (3.41084) 22:35: Rx1: The squelch is CLOSED (-2.28519) 22:35: Rx1: The squelch is OPEN (13.2694) 22:35: RepeaterLogic: digit=1 22:35: DTMF digit received in module MetarInfo: 1 22:35: RepeaterLogic: digit=# 22:35: DTMF digit received in module MetarInfo: # 22:35: Rx1: The squelch is CLOSED (-2.61216) 22:35: DTMF command received in module MetarInfo: 1 22:35: Rx1: The squelch is OPEN (1.32685) 22:35: Rx1: The squelch is CLOSED (-2.84068) 22:35: Rx1: The squelch is OPEN (27.6283) 22:35: RepeaterLogic: digit=1 22:35: DTMF digit received in module MetarInfo: 1 22:35: RepeaterLogic: digit=# 22:35: DTMF digit received in module MetarInfo: # 22:35: Rx1: The squelch is CLOSED (-2.54091) 22:35: DTMF command received in module MetarInfo: 1 22:35: Rx1: The squelch is OPEN (19.5316) 22:35: RepeaterLogic: digit=1 22:35: DTMF digit received in module MetarInfo: 1 22:35: RepeaterLogic: digit=# 22:35: DTMF digit received in module MetarInfo: # 22:35: RepeaterLogic: digit=# 22:35: DTMF digit received in module MetarInfo: # 08:18: Rx1: The squelch is CLOSED (-4.02337) 08:18: DTMF command received in module MetarInfo: 1 08:18: DTMF command received in module MetarInfo: 08:18: RepeaterLogic: Deactivating module MetarInfo... 08:18: pthread_mutex_destroy: error 10 08:18: 08:18: SIGTERM received. Shutting down application... 22:21: qnh 1003 22:22: Tx1: Turning the transmitter OFF 22:29: Rx1: The squelch is OPEN (-3.11959) 22:29: Rx1: The squelch is CLOSED (-1.90969) 22:29: Rx1: The squelch is OPEN (-3.12667) 22:29: Rx1: The squelch is CLOSED (-3.3631) 22:29: Rx1: The squelch is OPEN (-1.48948) 22:29: Rx1: The squelch is CLOSED (-1.02812) 22:29: Rx1: The squelch is OPEN (-0.0829903) 22:29: Rx1: The squelch is CLOSED (-1.37958) 22:29: Rx1: The squelch is OPEN (-0.274447) 22:29: Rx1: The squelch is CLOSED (-2.53714) 22:29: Rx1: The squelch is OPEN (-0.18243) 22:29: Rx1: The squelch is CLOSED (-1.62982) 22:29: Rx1: The squelch is OPEN (0.934452) 22:29: Rx1: The squelch is CLOSED (-1.56555) 22:30: RepeaterLogic: Sending short identification... 22:30: Tx1: Turning the transmitter ON 22:30: Tx1: Turning the transmitter OFF 22:34: Rx1: The squelch is OPEN (8.4036) 22:34: RepeaterLogic: 1750 Hz tone call detected 22:34: Rx1: The squelch is CLOSED (7.28353) 22:34: Tx1: Turning the transmitter ON 22:35: Rx1: The squelch is OPEN (8.06954) 22:35: Rx1: The squelch is CLOSED (-1.85359) 22:35: Rx1: The squelch is OPEN (8.46443) 22:35: Rx1: The squelch is CLOSED (-3.00242) 22:35: Rx1: The squelch is OPEN (7.97535) 22:35: RepeaterLogic: digit=5 22:35: RepeaterLogic: digit=# 22:35: RepeaterLogic: digit=# 22:35: Rx1: The squelch is CLOSED (-4.19778) 22:35: RepeaterLogic: Activating module MetarInfo... 22:35: DTMF command received in module MetarInfo: 22:35: RepeaterLogic: Deactivating module MetarInfo... 22:35: pthread_mutex_destroy: error 16 22:35: Rx1: The squelch is OPEN (22.3701) 22:35: RepeaterLogic: digit=5 22:35: RepeaterLogic: digit=# 22:36: Rx1: The squelch is CLOSED (-4.46372) 22:36: RepeaterLogic: Activating module MetarInfo... 22:36: Tx1: Turning the transmitter OFF 22:36: Rx1: The squelch is OPEN (4.81233) 22:36: RepeaterLogic: 1750 Hz tone call detected 22:36: Rx1: The squelch is CLOSED (6.55583) 22:36: Tx1: Turning the transmitter ON 22:36: Rx1: The squelch is OPEN (12.2789) 22:36: RepeaterLogic: digit=3 22:36: DTMF digit received in module MetarInfo: 3 22:36: RepeaterLogic: digit=# 22:36: DTMF digit received in module MetarInfo: # 22:36: Rx1: The squelch is CLOSED (-3.72128) 22:36: DTMF command received in module MetarInfo: 3 22:36: Tx1: Turning the transmitter OFF 22:36: Rx1: The squelch is OPEN (9.92351) 22:36: RepeaterLogic: 88 Hz tone call detected 22:36: Rx1: The squelch is CLOSED (13.272) 22:36: Tx1: Turning the transmitter ON 22:36: Rx1: The squelch is OPEN (7.71504) 22:36: RepeaterLogic: digit=# 22:36: DTMF digit received in module MetarInfo: # 22:36: RepeaterLogic: digit=# 22:36: DTMF digit received in module MetarInfo: # 22:37: RepeaterLogic: digit=# 22:37: DTMF digit received in module MetarInfo: # 07:31: SvxLink v1.4.99.2 (Oct 31 2014) Copyright (C) 2003-2014 Tobias Blomberg / SM0SVX 07:31: 07:31: SvxLink comes with ABSOLUTELY NO WARRANTY. This is free software, and you are 07:31: welcome to redistribute it in accordance with the terms and conditions in the 07:31: GNU GPL (General Public License) version 2 or later. 07:31: 07:31: Using configuration file: /etc/svxlink/svxlink.conf 07:31: --- Using sample rate 48000Hz 07:31: 07:31: Starting logic: RepeaterLogic 07:31: Loading RX: Rx1 07:31: *\ ERROR: Open capture audio device failed: Device or resource busy 07:31: * ERROR: Could not open audio device for receiver "Rx1" 07:31: * ERROR: Could not initialize RX "Rx1" 07:31: * ERROR: Could not initialize Logic object "RepeaterLogic". Skipping... 07:31: *\ ERROR: No logics available. Bailing out... 07:48: Rx1: The squelch is CLOSED (-2.91812) 07:48: DTMF command received in module MetarInfo: 07:48: RepeaterLogic: Deactivating module MetarInfo... 07:48: pthread_mutex_destroy: error 16 07:48: 07:48: SIGTERM received. Shutting down application...

f5vmr commented 9 years ago

Model B+ has had no issues since becoming operational on the Vhf repeater. Unless anyone still has a model B then I think can close this issue.

sm0svx commented 9 years ago

Ok, good. If someone have the same issue they can reopen the issue but it seems the problem is hardware related rather than software related, so the solution is to buy a B+. Thanks for reporting back!