21 Dec
2018
21 Dec
'18
8:48 a.m.
I have trx, bts, bsc, msc, stp, hlr, and sip installed...
asterisk runs on a separate machine, i.e. my ordinary pbx, with just the
recomended
changes to sip and extensions.
When dialling an external number I do not get any call progress
(ringing) in the MS.
Phone is quiet as I dial the number, when the call is answered voice is
"suddenly" there,
this is a difference from "latest" where call progress was audiable but
had only oneway audio.
I run HLR with the -U switch, there seems to be a difference between
"latest" and "nightly",
what does the -U switch do, modify the database, or just run HLR in
backward compatibility mode?
Should I delete / reregister phones?
Regards,
Gullik
21 Dec
21 Dec
9:38 a.m.
I have trx, bts, bsc, msc, stp, hlr, and sip installed...on a Orange PI
Zero.
asterisk runs on a separate machine.. SDR is Ettus B100 for now....
CPU is 4 core arm H2+, idle with stack running 75% idle, increasing to
90% with one call
active, i.e. lots of CPU left. Memory consumption 250 out of 512 M, so
plenty memory left.
In all -- impressive!!
A pocket-size GSM base station.
Gullik
11:26 a.m.
New subject: osmo-uhd-trx
I have also seen
Bug #3067
Where the uhd-trx continously logs packet loss. Killing the trx, and
restarting it, it recovers,
and operation is resumed. It seems to get into some unrecoverable loop.
This happens
rarely, I have seen it twice the last 24 hours. Will try to get a better
footprint.
Gullik
12:21 p.m.
New subject: osmo-uhd-trx
Hmm, is the event code actually generated by the uhd driver? It looks like
the definition of EVENT_CODE_SEQ_ERROR that generates this log item comes
from include/uhd/types/metadata.hpp
<https://files.ettus.com/manual/metadata_8hpp_source.html>
Gullik
|
bool uhd_device::recv_async_msg()
{
uhd::async_metadata_t md;
thread_enable_cancel(false);
bool rc = usrp_dev->get_device()->recv_async_msg(md);
thread_enable_cancel(true);
if (!rc)
return false;
// Assume that any error requires resynchronization
if (md.event_code != uhd::async_metadata_t::EVENT_CODE_BURST_ACK) {
aligned = false;
if ((md.event_code != uhd::async_metadata_t::EVENT_CODE_UNDERFLOW) &&
(md.event_code != uhd::async_metadata_t::EVENT_CODE_TIME_ERROR)) {
LOGC(DDEV, ERR) << str_code(md);
}
}
return true;
}|
22 Dec
22 Dec
9 a.m.
New subject: osmo-uhd-trx
At 3 am the trx stopped again. This time it exited (itself) after
logging large amounts of packet loss,
within 1 second or so....(as far back as the terminal history displays).
Restarting it signal came back within a few seconds.
UHD used: UHD_003.009.005-0-unknown installed with apt.
trx: osmo-trx-uhd_0.4.0.124.42c1_armhf.deb
It seems the interaction beween UHD and TRX is the problem, ( or the TRX
itself ) since just rerunning
trx fixes everything, and the rest of the BTS components seem
functionally intact.
Gullik
On 2018-12-21 13:21, Gullik Webjorn wrote:
Hmm, is the event code actually generated by the uhd driver? It looks like
the definition of EVENT_CODE_SEQ_ERROR that generates this log item comes
from include/uhd/types/metadata.hpp
<https://files.ettus.com/manual/metadata_8hpp_source.html>
Gullik
|
bool uhd_device::recv_async_msg()
{
uhd::async_metadata_t md;
thread_enable_cancel(false);
bool rc = usrp_dev->get_device()->recv_async_msg(md);
thread_enable_cancel(true);
if (!rc)
return false;
// Assume that any error requires resynchronization
if (md.event_code != uhd::async_metadata_t::EVENT_CODE_BURST_ACK) {
aligned = false;
if ((md.event_code != uhd::async_metadata_t::EVENT_CODE_UNDERFLOW) &&
(md.event_code != uhd::async_metadata_t::EVENT_CODE_TIME_ERROR)) {
LOGC(DDEV, ERR) << str_code(md);
}
}
return true;
}|
9:42 a.m.
New subject: osmo-uhd-trx
On Sat, Dec 22, 2018 at 10:00:50AM +0100, Gullik Webjorn wrote:
At 3 am the trx stopped again. This time it exited
(itself) after logging
large amounts of packet loss,
The interesting question is: Was there some kind of cron job or other activity
running at 3am on that system, which could cause a system load high enough to
make the flow between B100, kernel USB stack, libusb, UHD and osmo-trx-uhd
interrupt?
Something like this is likely the root cause of the problem.
Sure, osmo-trx could "plaster around" it by having a more elegant recovery
mechanism, but failing fast due to exit and letting osmo-trx-uhd respawn
(normally executed via systemd) isn't actually all too bad.
What's definitely a real problem that needs immediate fixing is if we
somehow get stack with osmo-trx continuing to run, but failing to
transmit a valid signal wihout exit + respawn.
Regards,
Harald
--
- Harald Welte <laforge(a)gnumonks.org> http://laforge.gnumonks.org/
============================================================================
"Privacy in residential applications is a desirable marketing option."
(ETSI EN 300 175-7 Ch. A6)
11:25 a.m.
New subject: osmo-uhd-trx
Hello Harald, long time.....
This is syslog for the time...
Dec 22 03:15:01 localhost CRON[25895]: (root) CMD (command -v debian-sa1
/dev/null && debian-sa1 1 1)
Dec 22
03:16:22 localhost osmo-bts-trx[18200]: #033[0;m<0007>
l1sap.c:510 1338262/1009/16/22/46 Invalid condition detected: Frame
difference is 1338262-1338205=57 > 1!
Dec 22 03:17:01 localhost CRON[25911]: (root) CMD ( cd / && run-parts
--report /etc/cron.hourly)
here trx uhd has logged lots of lost packets
03:36:19, so 2 seconds before next syslog entry, all within the same
second, filling the terminal buffer, so I cannot see loggings
immediately before
Dec 22 03:19:38 localhost osmo-bts-trx[18200]: #033[0;m#033[1;36m<0001>
bts.c:250 Shutting down BTS 0, Reason No clock from osmo-trx
Dec 22 03:19:41 localhost osmo-bts-trx[18200]: #033[0;mShutdown timer
expired
Dec 22 03:19:41 localhost osmo-bts-trx[18200]: ((*))
Dec 22 03:19:41 localhost osmo-bts-trx[18200]: |
Dec 22 03:19:41 localhost osmo-bts-trx[18200]: / \ OsmoBTS
Dec 22 03:19:41 localhost systemd[1]: osmo-bts-trx.service: Main process
exited, code=exited, status=42/n/a
Dec 22 03:19:41 localhost systemd[1]: osmo-bts-trx.service: Unit entered
failed state.
Dec 22 03:19:41 localhost systemd[1]: osmo-bts-trx.service: Failed with
result 'exit-code'.
Dec 22 03:19:43 localhost systemd[1]: osmo-bts-trx.service: Service
hold-off time over, scheduling restart.
Dec 22 03:19:43 localhost systemd[1]: Stopped Osmocom osmo-bts for osmo-trx.
Dec 22 03:19:43 localhost systemd[1]: Started Osmocom osmo-bts for osmo-trx.
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: <0017> control_if.c:911
CTRL at 127.0.0.1 4238
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m<0010>
telnet_interface.c:104 Available via telnet 127.0.0.1 4241
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m<0012>
input/ipaccess.c:882 enabling ipaccess BTS mode, OML connecting to
127.0.0.1:3002
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m#033[1;33m<000b>
trx_if.c:754 Open transceiver for phy0.0
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m<0012>
input/ipa.c:128 127.0.0.1:3002 connection done
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m<0012>
input/ipaccess.c:705 received ID get from 1801/0/0
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m#033[1;36m<0001>
oml.c:229 O&M Get Attributes [0], Manufacturer Dependent State is
unsupported by TRX.
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m#033[1;36m<0001>
oml.c:681 Ignoring T200[0] (150 ms) as sent by BSC due to suspected
LAPDm bug!
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m#033[1;36m<0001>
oml.c:681 Ignoring T200[1] (180 ms) as sent by BSC due to suspected
LAPDm bug!
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m#033[1;36m<0001>
oml.c:681 Ignoring T200[2] (180 ms) as sent by BSC due to suspected
LAPDm bug!
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m#033[1;36m<0001>
oml.c:681 Ignoring T200[3] (1680 ms) as sent by BSC due to suspected
LAPDm bug!
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m#033[1;36m<0001>
oml.c:681 Ignoring T200[4] (520 ms) as sent by BSC due to suspected
LAPDm bug!
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m#033[1;36m<0001>
oml.c:681 Ignoring T200[5] (165 ms) as sent by BSC due to suspected
LAPDm bug!
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m#033[1;36m<0001>
oml.c:681 Ignoring T200[6] (1680 ms) as sent by BSC due to suspected
LAPDm bug!
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m#033[1;36m<0001>
oml.c:1055 ADM state already was Unlocked
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m<0012>
input/ipa.c:128 127.0.0.1:3003 connection done
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m<0012>
input/ipaccess.c:705 received ID get from 1801/0/0
Dec 22 03:19:45 localhost osmo-bts-trx[25938]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 03:19:47 localhost osmo-bts-trx[25938]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 03:19:49 localhost osmo-bts-trx[25938]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
I just had the same stopping again, here is a snippet from that trx
terminal.........
Sat Dec 22 10:21:16 2018 DMAIN <0000> Transceiver.cpp:1016
[tid=3007554640] reduced latency: 3:9
Sat Dec 22 10:21:17 2018 DMAIN <0000> Transceiver.cpp:1039
[tid=3007521872] ClockInterface: sending IND CLOCK 292365
Sat Dec 22 10:21:17 2018 DMAIN <0000> Transceiver.cpp:1005
[tid=3007554640] new latency: 3:10 (underrun 3:292376 vs 1:292229)
Sat Dec 22 10:21:18 2018 DMAIN <0000> Transceiver.cpp:1039
[tid=3007521872] ClockInterface: sending IND CLOCK 292581
Sat Dec 22 10:21:18 2018 DMAIN <0000> Transceiver.cpp:1016
[tid=3007554640] reduced latency: 2:10
Sat Dec 22 10:21:19 2018 DMAIN <0000> Transceiver.cpp:1039
[tid=3007521872] ClockInterface: sending IND CLOCK 292797
Sat Dec 22 10:21:19 2018 DMAIN <0000> Transceiver.cpp:1016
[tid=3007554640] reduced latency: 1:10
Sat Dec 22 10:21:19 2018 DDEV <0002> UHDDevice.cpp:861 [tid=3007521872]
No packet received, implementation timed-out
Sat Dec 22 10:21:19 2018 DDEV <0002> UHDDevice.cpp:865 [tid=3007521872]
UHD: Receive timed out
Sat Dec 22 10:21:19 2018 DMAIN <0000> radioInterfaceResamp.cpp:178
[tid=3007521872] Receive error 0
Sat Dec 22 10:21:19 2018 DMAIN <0000> Transceiver.cpp:908
[tid=3007521872] radio Interface receive failed, requesting stop.
Sat Dec 22 10:21:19 2018 DMAIN <0000> Transceiver.cpp:1005
[tid=3007554640] new latency: 1:11 (underrun 0:292830 vs 0:292819)
Sat Dec 22 10:21:19 2018 DDEV <0002> UHDDevice.cpp:861 [tid=3007521872]
An internal receive buffer has filled at 3113.55 sec.
Sat Dec 22 10:21:20 2018 DDEV <0002> UHDDevice.cpp:1485 [tid=3007521872]
Skipping buffer data: timestamp=1245558064 time_end=1245418309
Sat Dec 22 10:21:20 2018 DMAIN <0000> Transceiver.cpp:1005
[tid=3007554640] new latency: 1:12 (underrun 3:292843 vs 2:292840)
Sat Dec 22 10:21:20 2018 DMAIN <0000> Transceiver.cpp:1005
[tid=3007554640] new latency: 1:13 (underrun 3:292854 vs 4:292853)
Sat Dec 22 10:21:20 2018 DMAIN <0000> osmo-trx.cpp:435 [tid=3025046000]
Shutting down transceiver...
Sat Dec 22 10:21:20 2018 DMAIN <0000> Transceiver.cpp:307
[tid=3025046000] Stopping the transceiver
Sat Dec 22 10:21:20 2018 DMAIN <0000> Transceiver.cpp:320
[tid=3025046000] Stopping the device
Sat Dec 22 10:21:20 2018 DMAIN <0000> Transceiver.cpp:333
[tid=3025046000] Transceiver stopped
This is syslog from right before this, I cut a few lines before the
first osmo-bts-trx logging at 10:00:26
It complains a few times within that few seconds....then at 10:11:08 ,
11, then stopping at 10:21:21
Dec 22 09:57:12 localhost dbus[779]: [system] Successfully activated
service 'org.freedesktop.nm_dispatcher'
Dec 22 09:57:12 localhost systemd[1]: Started Network Manager Script
Dispatcher Service.
Dec 22 09:57:12 localhost nm-dispatcher: req:1 'dhcp4-change' [eth0]:
new request (2 scripts)
Dec 22 09:57:12 localhost nm-dispatcher: req:1 'dhcp4-change' [eth0]:
start running ordered scripts...
Dec 22 10:00:01 localhost CRON[29739]: (root) CMD
(/usr/lib/armbian/armbian-truncate-logs)
Dec 22 10:00:26 localhost osmo-bts-trx[25938]: #033[0;m#033[1;35m<0000>
rsl.c:741 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN ACT ACK
Dec 22 10:00:26 localhost osmo-bts-trx[25938]: #033[0;m<0011>
lapd_core.c:920 Store content res. (dl=0xb681b498)
Dec 22 10:00:27 localhost osmo-bts-trx[25938]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb681b498
state LAPD_STATE_MF_EST)
Dec 22 10:00:27 localhost osmo-bts-trx[25938]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb681b498
state LAPD_STATE_MF_EST)
Dec 22 10:00:28 localhost osmo-bts-trx[25938]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb681b498
state LAPD_STATE_MF_EST)
Dec 22 10:00:29 localhost osmo-bts-trx[25938]: #033[0;m#033[1;35m<0000>
rsl.c:720 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN REL ACK
Dec 22 10:05:01 localhost CRON[29783]: (root) CMD (command -v debian-sa1
/dev/null && debian-sa1 1 1)
Dec 22
10:11:08 localhost osmo-bts-trx[25938]: #033[0;m#033[1;35m<0000>
rsl.c:741 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN ACT ACK
Dec 22 10:11:11 localhost osmo-bts-trx[25938]: #033[0;m#033[1;35m<0000>
rsl.c:720 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN REL ACK
Dec 22 10:15:01 localhost CRON[29858]: (root) CMD
(/usr/lib/armbian/armbian-truncate-logs)
Dec 22 10:15:02 localhost CRON[29859]: (root) CMD (command -v debian-sa1
/dev/null && debian-sa1 1 1)
Dec 22
10:17:01 localhost CRON[29877]: (root) CMD ( cd / && run-parts
--report /etc/cron.hourly)
Dec 22 10:21:21 localhost osmo-bts-trx[25938]: #033[0;m#033[1;36m<0001>
bts.c:250 Shutting down BTS 0, Reason No clock from osmo-trx
Dec 22 10:21:24 localhost osmo-bts-trx[25938]: #033[0;mShutdown timer
expired
Dec 22 10:21:24 localhost osmo-bts-trx[25938]: ((*))
Dec 22 10:21:24 localhost osmo-bts-trx[25938]: |
Dec 22 10:21:24 localhost osmo-bts-trx[25938]: / \ OsmoBTS
Dec 22 10:21:24 localhost systemd[1]: osmo-bts-trx.service: Main process
exited, code=exited, status=42/n/a
Dec 22 10:21:24 localhost systemd[1]: osmo-bts-trx.service: Unit entered
failed state.
Dec 22 10:21:24 localhost systemd[1]: osmo-bts-trx.service: Failed with
result 'exit-code'.
Dec 22 10:21:26 localhost systemd[1]: osmo-bts-trx.service: Service
hold-off time over, scheduling restart.
Dec 22 10:21:26 localhost systemd[1]: Stopped Osmocom osmo-bts for osmo-trx.
Dec 22 10:21:26 localhost systemd[1]: Started Osmocom osmo-bts for osmo-trx.
Dec 22 10:21:26 localhost osmo-bts-trx[29913]: <0017> control_if.c:911
CTRL at 127.0.0.1 4238
Dec 22 10:21:26 localhost osmo-bts-trx[29913]: #033[0;m<0010>
telnet_interface.c:104 Available via telnet 127.0.0.1 4241
Dec 22 10:21:26 localhost osmo-bts-trx[29913]: #033[0;m<0012>
input/ipaccess.c:882 enabling ipaccess BTS mode, OML connecting to
127.0.0.1:3002
Dec 22 10:21:26 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:754 Open transceiver for phy0.0
Dec 22 10:21:26 localhost osmo-bts-trx[29913]: #033[0;m<0012>
input/ipa.c:128 127.0.0.1:3002 connection done
Dec 22 10:21:26 localhost osmo-bts-trx[29913]: #033[0;m<0012>
input/ipaccess.c:705 received ID get from 1801/0/0
Dec 22 10:21:26 localhost osmo-bts-trx[29913]: #033[0;m#033[1;36m<0001>
oml.c:229 O&M Get Attributes [0], Manufacturer Dependent State is
unsupported by TRX.
Dec 22 10:21:26 localhost osmo-bts-trx[29913]: #033[0;m#033[1;36m<0001>
oml.c:681 Ignoring T200[0] (150 ms) as sent by BSC due to suspected
LAPDm bug!
Dec 22 10:21:26 localhost osmo-bts-trx[29913]: #033[0;m#033[1;36m<0001>
oml.c:681 Ignoring T200[1] (180 ms) as sent by BSC due to suspected
LAPDm bug!
Dec 22 10:21:26 localhost osmo-bts-trx[29913]: #033[0;m#033[1;36m<0001>
oml.c:681 Ignoring T200[2] (180 ms) as sent by BSC due to suspected
LAPDm bug!
Dec 22 10:21:26 localhost osmo-bts-trx[29913]: #033[0;m#033[1;36m<0001>
oml.c:681 Ignoring T200[3] (1680 ms) as sent by BSC due to suspected
LAPDm bug!
Dec 22 10:21:26 localhost osmo-bts-trx[29913]: #033[0;m#033[1;36m<0001>
oml.c:681 Ignoring T200[4] (520 ms) as sent by BSC due to suspected
LAPDm bug!
Dec 22 10:21:26 localhost osmo-bts-trx[29913]: #033[0;m#033[1;36m<0001>
oml.c:681 Ignoring T200[5] (165 ms) as sent by BSC due to suspected
LAPDm bug!
Dec 22 10:21:26 localhost osmo-bts-trx[29913]: #033[0;m#033[1;36m<0001>
oml.c:681 Ignoring T200[6] (1680 ms) as sent by BSC due to suspected
LAPDm bug!
Dec 22 10:21:26 localhost osmo-bts-trx[29913]: #033[0;m#033[1;36m<0001>
oml.c:1055 ADM state already was Unlocked
Dec 22 10:21:27 localhost osmo-bts-trx[29913]: #033[0;m<0012>
input/ipa.c:128 127.0.0.1:3003 connection done
Dec 22 10:21:27 localhost osmo-bts-trx[29913]: #033[0;m<0012>
input/ipaccess.c:705 received ID get from 1801/0/0
Dec 22 10:21:28 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 10:21:30 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 10:21:32 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 10:21:34 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 10:21:36 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 10:21:38 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 10:21:40 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 10:21:42 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 10:21:44 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 10:21:46 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 10:21:48 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 10:21:50 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 10:21:52 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 10:21:54 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 10:21:56 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 10:21:58 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 10:22:00 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 10:22:02 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 10:22:04 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 10:22:06 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 10:22:08 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 10:22:10 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 10:22:11 localhost dhclient[5395]: DHCPREQUEST of 192.168.1.170
on eth0 to 192.168.1.1 port 67
Dec 22 10:22:11 localhost dhclient[5395]: DHCPACK of 192.168.1.170 from
192.168.1.1
Dec 22 10:22:11 localhost NetworkManager[789]: <info> [1545470531.2789]
dhcp4 (eth0): address 192.168.1.170
Dec 22 10:22:11 localhost NetworkManager[789]: <info> [1545470531.2791]
dhcp4 (eth0): plen 24 (255.255.255.0)
Dec 22 10:22:11 localhost NetworkManager[789]: <info> [1545470531.2792]
dhcp4 (eth0): gateway 192.168.1.1
Dec 22 10:22:11 localhost NetworkManager[789]: <info> [1545470531.2793]
dhcp4 (eth0): server identifier 192.168.1.1
Dec 22 10:22:11 localhost NetworkManager[789]: <info> [1545470531.2793]
dhcp4 (eth0): lease time 3600
Dec 22 10:22:11 localhost NetworkManager[789]: <info> [1545470531.2794]
dhcp4 (eth0): hostname 'orangepizero'
Dec 22 10:22:11 localhost NetworkManager[789]: <info> [1545470531.2795]
dhcp4 (eth0): nameserver '192.168.1.1'
Dec 22 10:22:11 localhost dbus[779]: [system] Activating via systemd:
service name='org.freedesktop.nm_dispatcher'
unit='dbus-org.freedesktop.nm-dispatcher.service'
Dec 22 10:22:11 localhost NetworkManager[789]: <info> [1545470531.2796]
dhcp4 (eth0): domain name 'lan'
Dec 22 10:22:11 localhost NetworkManager[789]: <info> [1545470531.2797]
dhcp4 (eth0): state changed bound -> bound
Dec 22 10:22:11 localhost systemd[1]: Starting Network Manager Script
Dispatcher Service...
Dec 22 10:22:11 localhost dhclient[5395]: bound to 192.168.1.170 --
renewal in 1598 seconds.
Dec 22 10:22:11 localhost dbus[779]: [system] Successfully activated
service 'org.freedesktop.nm_dispatcher'
Dec 22 10:22:11 localhost systemd[1]: Started Network Manager Script
Dispatcher Service.
Dec 22 10:22:11 localhost nm-dispatcher: req:1 'dhcp4-change' [eth0]:
new request (2 scripts)
Dec 22 10:22:11 localhost nm-dispatcher: req:1 'dhcp4-change' [eth0]:
start running ordered scripts...
Dec 22 10:22:12 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 10:22:14 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 10:22:16 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 10:22:18 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 10:22:20 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 10:22:22 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Then, as I restart trx-uhd again, ( by kbd uparrow <cr> ) carrier comes
back and phone registers within a few seconds.....
I see nothing upsetting in syslog that could explain cpu outage,
besides, this is a 4-core Orange Pi Zero, I do not however know what quirks
in Armbian Linux could lock out processing, when total load is 95% or so
out of 400% ( i.e. 75% idle )
If there is anything I could do to bring clarity, please suggest....
Regards,
Gullik
On 2018-12-22 10:42, Harald Welte wrote:
On Sat, Dec 22, 2018 at 10:00:50AM +0100, Gullik
Webjorn wrote:
I will investigate as I possibly can
At 3 am the trx stopped again. This time it
exited (itself) after logging
large amounts of packet loss,
The interesting question is: Was there some kind of
cron job or other activity
running at 3am on that system, which could cause a system load high enough to
make the flow between B100, kernel USB stack, libusb, UHD and osmo-trx-uhd
interrupt?
Something like this is likely the root cause of the problem.
Sure, osmo-trx could "plaster around" it by having a more elegant recovery
mechanism, but failing fast due to exit and letting osmo-trx-uhd respawn
(normally executed via systemd) isn't actually all too bad.
What's definitely a real problem that needs immediate fixing is if we
somehow get stack with osmo-trx continuing to run, but failing to
transmit a valid signal wihout exit + respawn.
That HAS happened for me, with the
screen filled with logging of packet
loss, pointing at line 1319 in
|
uhd_device::recv_async_msg() |
Regards,
Harald
12:32 p.m.
New subject: osmo-uhd-trx
Hello Gullik,
If possible please set up some kind of monitoring of key system parameters (load, memory
etc.) so we can determine if there is any irregularities happening before the issue.
Also it would help us to see if there is any regularity in the time intervals the issue
happens.
I for my servers use Zabbix for this, but it would be way too complicated I think for this
purpose.
So any simple monitoring system that retains historic data (for the last, let’s say 24
hours) would be good.
Just my 2cents...
Domi
2018. dec. 22. dátummal, 12:25 időpontban Gullik Webjorn
<gullik.webjorn(a)corevalue.se> írta:
Hello Harald, long time.....
This is syslog for the time...
Dec 22 03:15:01 localhost CRON[25895]: (root) CMD (command -v debian-sa1 > /dev/null
&& debian-sa1 1 1)
Dec 22 03:16:22 localhost osmo-bts-trx[18200]: #033[0;m<0007> l1sap.c:510
1338262/1009/16/22/46 Invalid condition detected: Frame difference is 1338262-1338205=57
> 1!
Dec 22 03:17:01 localhost CRON[25911]: (root) CMD ( cd / && run-parts --report
/etc/cron.hourly)
here trx uhd has logged lots of lost packets
03:36:19, so 2 seconds before next syslog entry, all within the same second, filling the
terminal buffer, so I cannot see loggings immediately before
Dec 22 03:19:38 localhost osmo-bts-trx[18200]: #033[0;m#033[1;36m<0001> bts.c:250
Shutting down BTS 0, Reason No clock from osmo-trx
Dec 22 03:19:41 localhost osmo-bts-trx[18200]: #033[0;mShutdown timer expired
Dec 22 03:19:41 localhost osmo-bts-trx[18200]: ((*))
Dec 22 03:19:41 localhost osmo-bts-trx[18200]: |
Dec 22 03:19:41 localhost osmo-bts-trx[18200]: / \ OsmoBTS
Dec 22 03:19:41 localhost systemd[1]: osmo-bts-trx.service: Main process exited,
code=exited, status=42/n/a
Dec 22 03:19:41 localhost systemd[1]: osmo-bts-trx.service: Unit entered failed state.
Dec 22 03:19:41 localhost systemd[1]: osmo-bts-trx.service: Failed with result
'exit-code'.
Dec 22 03:19:43 localhost systemd[1]: osmo-bts-trx.service: Service hold-off time over,
scheduling restart.
Dec 22 03:19:43 localhost systemd[1]: Stopped Osmocom osmo-bts for osmo-trx.
Dec 22 03:19:43 localhost systemd[1]: Started Osmocom osmo-bts for osmo-trx.
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: <0017> control_if.c:911 CTRL at
127.0.0.1 4238
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m<0010>
telnet_interface.c:104 Available via telnet 127.0.0.1 4241
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m<0012> input/ipaccess.c:882
enabling ipaccess BTS mode, OML connecting to 127.0.0.1:3002
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m#033[1;33m<000b>
trx_if.c:754 Open transceiver for phy0.0
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m<0012> input/ipa.c:128
127.0.0.1:3002 connection done
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m<0012> input/ipaccess.c:705
received ID get from 1801/0/0
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m#033[1;36m<0001> oml.c:229
O&M Get Attributes [0], Manufacturer Dependent State is unsupported by TRX.
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m#033[1;36m<0001> oml.c:681
Ignoring T200[0] (150 ms) as sent by BSC due to suspected LAPDm bug!
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m#033[1;36m<0001> oml.c:681
Ignoring T200[1] (180 ms) as sent by BSC due to suspected LAPDm bug!
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m#033[1;36m<0001> oml.c:681
Ignoring T200[2] (180 ms) as sent by BSC due to suspected LAPDm bug!
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m#033[1;36m<0001> oml.c:681
Ignoring T200[3] (1680 ms) as sent by BSC due to suspected LAPDm bug!
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m#033[1;36m<0001> oml.c:681
Ignoring T200[4] (520 ms) as sent by BSC due to suspected LAPDm bug!
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m#033[1;36m<0001> oml.c:681
Ignoring T200[5] (165 ms) as sent by BSC due to suspected LAPDm bug!
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m#033[1;36m<0001> oml.c:681
Ignoring T200[6] (1680 ms) as sent by BSC due to suspected LAPDm bug!
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m#033[1;36m<0001> oml.c:1055
ADM state already was Unlocked
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m<0012> input/ipa.c:128
127.0.0.1:3003 connection done
Dec 22 03:19:43 localhost osmo-bts-trx[25938]: #033[0;m<0012> input/ipaccess.c:705
received ID get from 1801/0/0
Dec 22 03:19:45 localhost osmo-bts-trx[25938]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD POWEROFF)
Dec 22 03:19:47 localhost osmo-bts-trx[25938]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD POWEROFF)
Dec 22 03:19:49 localhost osmo-bts-trx[25938]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD POWEROFF)
I just had the same stopping again, here is a snippet from that trx terminal.........
Sat Dec 22 10:21:16 2018 DMAIN <0000> Transceiver.cpp:1016 [tid=3007554640] reduced
latency: 3:9
Sat Dec 22 10:21:17 2018 DMAIN <0000> Transceiver.cpp:1039 [tid=3007521872]
ClockInterface: sending IND CLOCK 292365
Sat Dec 22 10:21:17 2018 DMAIN <0000> Transceiver.cpp:1005 [tid=3007554640] new
latency: 3:10 (underrun 3:292376 vs 1:292229)
Sat Dec 22 10:21:18 2018 DMAIN <0000> Transceiver.cpp:1039 [tid=3007521872]
ClockInterface: sending IND CLOCK 292581
Sat Dec 22 10:21:18 2018 DMAIN <0000> Transceiver.cpp:1016 [tid=3007554640] reduced
latency: 2:10
Sat Dec 22 10:21:19 2018 DMAIN <0000> Transceiver.cpp:1039 [tid=3007521872]
ClockInterface: sending IND CLOCK 292797
Sat Dec 22 10:21:19 2018 DMAIN <0000> Transceiver.cpp:1016 [tid=3007554640] reduced
latency: 1:10
Sat Dec 22 10:21:19 2018 DDEV <0002> UHDDevice.cpp:861 [tid=3007521872] No packet
received, implementation timed-out
Sat Dec 22 10:21:19 2018 DDEV <0002> UHDDevice.cpp:865 [tid=3007521872] UHD:
Receive timed out
Sat Dec 22 10:21:19 2018 DMAIN <0000> radioInterfaceResamp.cpp:178 [tid=3007521872]
Receive error 0
Sat Dec 22 10:21:19 2018 DMAIN <0000> Transceiver.cpp:908 [tid=3007521872] radio
Interface receive failed, requesting stop.
Sat Dec 22 10:21:19 2018 DMAIN <0000> Transceiver.cpp:1005 [tid=3007554640] new
latency: 1:11 (underrun 0:292830 vs 0:292819)
Sat Dec 22 10:21:19 2018 DDEV <0002> UHDDevice.cpp:861 [tid=3007521872] An internal
receive buffer has filled at 3113.55 sec.
Sat Dec 22 10:21:20 2018 DDEV <0002> UHDDevice.cpp:1485 [tid=3007521872] Skipping
buffer data: timestamp=1245558064 time_end=1245418309
Sat Dec 22 10:21:20 2018 DMAIN <0000> Transceiver.cpp:1005 [tid=3007554640] new
latency: 1:12 (underrun 3:292843 vs 2:292840)
Sat Dec 22 10:21:20 2018 DMAIN <0000> Transceiver.cpp:1005 [tid=3007554640] new
latency: 1:13 (underrun 3:292854 vs 4:292853)
Sat Dec 22 10:21:20 2018 DMAIN <0000> osmo-trx.cpp:435 [tid=3025046000] Shutting
down transceiver...
Sat Dec 22 10:21:20 2018 DMAIN <0000> Transceiver.cpp:307 [tid=3025046000] Stopping
the transceiver
Sat Dec 22 10:21:20 2018 DMAIN <0000> Transceiver.cpp:320 [tid=3025046000] Stopping
the device
Sat Dec 22 10:21:20 2018 DMAIN <0000> Transceiver.cpp:333 [tid=3025046000]
Transceiver stopped
This is syslog from right before this, I cut a few lines before the first osmo-bts-trx
logging at 10:00:26
It complains a few times within that few seconds....then at 10:11:08 , 11, then stopping
at 10:21:21
Dec 22 09:57:12 localhost dbus[779]: [system] Successfully activated service
'org.freedesktop.nm_dispatcher'
Dec 22 09:57:12 localhost systemd[1]: Started Network Manager Script Dispatcher
Service.
Dec 22 09:57:12 localhost nm-dispatcher: req:1 'dhcp4-change' [eth0]: new request
(2 scripts)
Dec 22 09:57:12 localhost nm-dispatcher: req:1 'dhcp4-change' [eth0]: start
running ordered scripts...
Dec 22 10:00:01 localhost CRON[29739]: (root) CMD
(/usr/lib/armbian/armbian-truncate-logs)
Dec 22 10:00:26 localhost osmo-bts-trx[25938]: #033[0;m#033[1;35m<0000> rsl.c:741
(bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN ACT ACK
Dec 22 10:00:26 localhost osmo-bts-trx[25938]: #033[0;m<0011> lapd_core.c:920 Store
content res. (dl=0xb681b498)
Dec 22 10:00:27 localhost osmo-bts-trx[25938]: #033[0;m<0011> lapd_core.c:1556 N(S)
sequence error: N(S)=0, V(R)=1 (dl=0xb681b498 state LAPD_STATE_MF_EST)
Dec 22 10:00:27 localhost osmo-bts-trx[25938]: #033[0;m<0011> lapd_core.c:1556 N(S)
sequence error: N(S)=0, V(R)=1 (dl=0xb681b498 state LAPD_STATE_MF_EST)
Dec 22 10:00:28 localhost osmo-bts-trx[25938]: #033[0;m<0011> lapd_core.c:1556 N(S)
sequence error: N(S)=0, V(R)=1 (dl=0xb681b498 state LAPD_STATE_MF_EST)
Dec 22 10:00:29 localhost osmo-bts-trx[25938]: #033[0;m#033[1;35m<0000> rsl.c:720
(bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN REL ACK
Dec 22 10:05:01 localhost CRON[29783]: (root) CMD (command -v debian-sa1 > /dev/null
&& debian-sa1 1 1)
Dec 22 10:11:08 localhost osmo-bts-trx[25938]: #033[0;m#033[1;35m<0000> rsl.c:741
(bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN ACT ACK
Dec 22 10:11:11 localhost osmo-bts-trx[25938]: #033[0;m#033[1;35m<0000> rsl.c:720
(bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN REL ACK
Dec 22 10:15:01 localhost CRON[29858]: (root) CMD
(/usr/lib/armbian/armbian-truncate-logs)
Dec 22 10:15:02 localhost CRON[29859]: (root) CMD (command -v debian-sa1 > /dev/null
&& debian-sa1 1 1)
Dec 22 10:17:01 localhost CRON[29877]: (root) CMD ( cd / && run-parts --report
/etc/cron.hourly)
Dec 22 10:21:21 localhost osmo-bts-trx[25938]: #033[0;m#033[1;36m<0001> bts.c:250
Shutting down BTS 0, Reason No clock from osmo-trx
Dec 22 10:21:24 localhost osmo-bts-trx[25938]: #033[0;mShutdown timer expired
Dec 22 10:21:24 localhost osmo-bts-trx[25938]: ((*))
Dec 22 10:21:24 localhost osmo-bts-trx[25938]: |
Dec 22 10:21:24 localhost osmo-bts-trx[25938]: / \ OsmoBTS
Dec 22 10:21:24 localhost systemd[1]: osmo-bts-trx.service: Main process exited,
code=exited, status=42/n/a
Dec 22 10:21:24 localhost systemd[1]: osmo-bts-trx.service: Unit entered failed state.
Dec 22 10:21:24 localhost systemd[1]: osmo-bts-trx.service: Failed with result
'exit-code'.
Dec 22 10:21:26 localhost systemd[1]: osmo-bts-trx.service: Service hold-off time over,
scheduling restart.
Dec 22 10:21:26 localhost systemd[1]: Stopped Osmocom osmo-bts for osmo-trx.
Dec 22 10:21:26 localhost systemd[1]: Started Osmocom osmo-bts for osmo-trx.
Dec 22 10:21:26 localhost osmo-bts-trx[29913]: <0017> control_if.c:911 CTRL at
127.0.0.1 4238
Dec 22 10:21:26 localhost osmo-bts-trx[29913]: #033[0;m<0010>
telnet_interface.c:104 Available via telnet 127.0.0.1 4241
Dec 22 10:21:26 localhost osmo-bts-trx[29913]: #033[0;m<0012> input/ipaccess.c:882
enabling ipaccess BTS mode, OML connecting to 127.0.0.1:3002
Dec 22 10:21:26 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:754 Open transceiver for phy0.0
Dec 22 10:21:26 localhost osmo-bts-trx[29913]: #033[0;m<0012> input/ipa.c:128
127.0.0.1:3002 connection done
Dec 22 10:21:26 localhost osmo-bts-trx[29913]: #033[0;m<0012> input/ipaccess.c:705
received ID get from 1801/0/0
Dec 22 10:21:26 localhost osmo-bts-trx[29913]: #033[0;m#033[1;36m<0001> oml.c:229
O&M Get Attributes [0], Manufacturer Dependent State is unsupported by TRX.
Dec 22 10:21:26 localhost osmo-bts-trx[29913]: #033[0;m#033[1;36m<0001> oml.c:681
Ignoring T200[0] (150 ms) as sent by BSC due to suspected LAPDm bug!
Dec 22 10:21:26 localhost osmo-bts-trx[29913]: #033[0;m#033[1;36m<0001> oml.c:681
Ignoring T200[1] (180 ms) as sent by BSC due to suspected LAPDm bug!
Dec 22 10:21:26 localhost osmo-bts-trx[29913]: #033[0;m#033[1;36m<0001> oml.c:681
Ignoring T200[2] (180 ms) as sent by BSC due to suspected LAPDm bug!
Dec 22 10:21:26 localhost osmo-bts-trx[29913]: #033[0;m#033[1;36m<0001> oml.c:681
Ignoring T200[3] (1680 ms) as sent by BSC due to suspected LAPDm bug!
Dec 22 10:21:26 localhost osmo-bts-trx[29913]: #033[0;m#033[1;36m<0001> oml.c:681
Ignoring T200[4] (520 ms) as sent by BSC due to suspected LAPDm bug!
Dec 22 10:21:26 localhost osmo-bts-trx[29913]: #033[0;m#033[1;36m<0001> oml.c:681
Ignoring T200[5] (165 ms) as sent by BSC due to suspected LAPDm bug!
Dec 22 10:21:26 localhost osmo-bts-trx[29913]: #033[0;m#033[1;36m<0001> oml.c:681
Ignoring T200[6] (1680 ms) as sent by BSC due to suspected LAPDm bug!
Dec 22 10:21:26 localhost osmo-bts-trx[29913]: #033[0;m#033[1;36m<0001> oml.c:1055
ADM state already was Unlocked
Dec 22 10:21:27 localhost osmo-bts-trx[29913]: #033[0;m<0012> input/ipa.c:128
127.0.0.1:3003 connection done
Dec 22 10:21:27 localhost osmo-bts-trx[29913]: #033[0;m<0012> input/ipaccess.c:705
received ID get from 1801/0/0
Dec 22 10:21:28 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD POWEROFF)
Dec 22 10:21:30 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD POWEROFF)
Dec 22 10:21:32 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD POWEROFF)
Dec 22 10:21:34 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD POWEROFF)
Dec 22 10:21:36 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD POWEROFF)
Dec 22 10:21:38 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD POWEROFF)
Dec 22 10:21:40 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD POWEROFF)
Dec 22 10:21:42 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD POWEROFF)
Dec 22 10:21:44 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD POWEROFF)
Dec 22 10:21:46 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD POWEROFF)
Dec 22 10:21:48 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD POWEROFF)
Dec 22 10:21:50 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD POWEROFF)
Dec 22 10:21:52 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD POWEROFF)
Dec 22 10:21:54 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD POWEROFF)
Dec 22 10:21:56 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD POWEROFF)
Dec 22 10:21:58 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD POWEROFF)
Dec 22 10:22:00 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD POWEROFF)
Dec 22 10:22:02 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD POWEROFF)
Dec 22 10:22:04 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD POWEROFF)
Dec 22 10:22:06 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD POWEROFF)
Dec 22 10:22:08 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD POWEROFF)
Dec 22 10:22:10 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD POWEROFF)
Dec 22 10:22:11 localhost dhclient[5395]: DHCPREQUEST of 192.168.1.170 on eth0 to
192.168.1.1 port 67
Dec 22 10:22:11 localhost dhclient[5395]: DHCPACK of 192.168.1.170 from 192.168.1.1
Dec 22 10:22:11 localhost NetworkManager[789]: <info> [1545470531.2789] dhcp4
(eth0): address 192.168.1.170
Dec 22 10:22:11 localhost NetworkManager[789]: <info> [1545470531.2791] dhcp4
(eth0): plen 24 (255.255.255.0)
Dec 22 10:22:11 localhost NetworkManager[789]: <info> [1545470531.2792] dhcp4
(eth0): gateway 192.168.1.1
Dec 22 10:22:11 localhost NetworkManager[789]: <info> [1545470531.2793] dhcp4
(eth0): server identifier 192.168.1.1
Dec 22 10:22:11 localhost NetworkManager[789]: <info> [1545470531.2793] dhcp4
(eth0): lease time 3600
Dec 22 10:22:11 localhost NetworkManager[789]: <info> [1545470531.2794] dhcp4
(eth0): hostname 'orangepizero'
Dec 22 10:22:11 localhost NetworkManager[789]: <info> [1545470531.2795] dhcp4
(eth0): nameserver '192.168.1.1'
Dec 22 10:22:11 localhost dbus[779]: [system] Activating via systemd: service
name='org.freedesktop.nm_dispatcher'
unit='dbus-org.freedesktop.nm-dispatcher.service'
Dec 22 10:22:11 localhost NetworkManager[789]: <info> [1545470531.2796] dhcp4
(eth0): domain name 'lan'
Dec 22 10:22:11 localhost NetworkManager[789]: <info> [1545470531.2797] dhcp4
(eth0): state changed bound -> bound
Dec 22 10:22:11 localhost systemd[1]: Starting Network Manager Script Dispatcher
Service...
Dec 22 10:22:11 localhost dhclient[5395]: bound to 192.168.1.170 -- renewal in 1598
seconds.
Dec 22 10:22:11 localhost dbus[779]: [system] Successfully activated service
'org.freedesktop.nm_dispatcher'
Dec 22 10:22:11 localhost systemd[1]: Started Network Manager Script Dispatcher
Service.
Dec 22 10:22:11 localhost nm-dispatcher: req:1 'dhcp4-change' [eth0]: new request
(2 scripts)
Dec 22 10:22:11 localhost nm-dispatcher: req:1 'dhcp4-change' [eth0]: start
running ordered scripts...
Dec 22 10:22:12 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD POWEROFF)
Dec 22 10:22:14 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD POWEROFF)
Dec 22 10:22:16 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD POWEROFF)
Dec 22 10:22:18 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD POWEROFF)
Dec 22 10:22:20 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD POWEROFF)
Dec 22 10:22:22 localhost osmo-bts-trx[29913]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD POWEROFF)
Then, as I restart trx-uhd again, ( by kbd uparrow <cr> ) carrier comes back and
phone registers within a few seconds.....
I see nothing upsetting in syslog that could explain cpu outage, besides, this is a
4-core Orange Pi Zero, I do not however know what quirks
in Armbian Linux could lock out processing, when total load is 95% or so out of 400% (
i.e. 75% idle )
If there is anything I could do to bring clarity, please suggest....
Regards,
Gullik
On 2018-12-22 10:42, Harald Welte wrote:
I will investigate as I possibly can
On Sat, Dec 22, 2018 at 10:00:50AM +0100, Gullik
Webjorn wrote:
At 3 am the trx stopped again. This time it exited (itself) after logging
large amounts of packet loss,
The interesting question is: Was there some kind of cron job or other activity
running at 3am on that system, which could cause a system load high enough to
make the flow between B100, kernel USB stack, libusb, UHD and osmo-trx-uhd
interrupt?
Something like this is likely the root cause of the problem.
Sure, osmo-trx could "plaster around" it by having a more elegant recovery
mechanism, but failing fast due to exit and letting osmo-trx-uhd respawn
(normally executed via systemd) isn't actually all too bad.
What's definitely a real problem that needs immediate fixing is if we
somehow get stack with osmo-trx continuing to run, but failing to
transmit a valid signal wihout exit + respawn.
That HAS happened for me, with the screen filled with logging of packet loss,
pointing at line 1319 in
uhd_device::recv_async_msg()
>
> Regards,
> Harald
6:38 p.m.
New subject: osmo-uhd-trx
What's definitely a real problem that needs
immediate fixing is if we
somehow get stack with osmo-trx continuing to run, but failing to
transmit a valid signal wihout exit + respawn.
Regards,
Harald
Well, here a footprint from the trx-uhd console.
I interrupted the process with a ^c at the end, carrier was lost, when
restarted by a kbd ^ everything went back to normal
and MS associated without manual intervention.
Sorry to clutter the list with long logs, hoping you might spot
something.......
Gullik
Sat Dec 22 19:22:40 2018 DMAIN <0000> Transceiver.cpp:1005
[tid=3008439376] new latency: 0:204923 (underrun 0:42138 vs 3:42136)
Sat Dec 22 19:22:40 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.1 sec.
Sat Dec 22 19:22:40 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.1 sec.
Sat Dec 22 19:22:40 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.1 sec.
Sat Dec 22 19:22:40 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.1 sec.
Sat Dec 22 19:22:40 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.1 sec.
Sat Dec 22 19:22:40 2018 DMAIN <0000> Transceiver.cpp:1005
[tid=3008439376] new latency: 0:204924 (underrun 5:42149 vs 0:42148)
Sat Dec 22 19:22:40 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.1 sec.
Sat Dec 22 19:22:40 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.1 sec.
Sat Dec 22 19:22:40 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.2 sec.
Sat Dec 22 19:22:40 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.2 sec.
Sat Dec 22 19:22:40 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.2 sec.
Sat Dec 22 19:22:40 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.2 sec.
Sat Dec 22 19:22:40 2018 DMAIN <0000> Transceiver.cpp:1005
[tid=3008439376] new latency: 0:204925 (underrun 2:42161 vs 5:42159)
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.2 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.2 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.2 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.2 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.2 sec.
Sat Dec 22 19:22:41 2018 DMAIN <0000> Transceiver.cpp:1005
[tid=3008439376] new latency: 0:204926 (underrun 7:42172 vs 2:42171)
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.3 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.3 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.3 sec.
Sat Dec 22 19:22:41 2018 DMAIN <0000> Transceiver.cpp:1005
[tid=3008439376] new latency: 0:204927 (underrun 3:42184 vs 7:42182)
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.3 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.3 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.3 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.3 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.3 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.3 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.3 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.3 sec.
Sat Dec 22 19:22:41 2018 DMAIN <0000> Transceiver.cpp:1005
[tid=3008439376] new latency: 0:204928 (underrun 5:42196 vs 3:42194)
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.4 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.4 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.4 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.4 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.4 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.4 sec.
Sat Dec 22 19:22:41 2018 DMAIN <0000> Transceiver.cpp:1005
[tid=3008439376] new latency: 0:204929 (underrun 6:42208 vs 5:42206)
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.4 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.4 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.4 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.5 sec.
Sat Dec 22 19:22:41 2018 DMAIN <0000> Transceiver.cpp:1005
[tid=3008439376] new latency: 0:204930 (underrun 1:42220 vs 6:42218)
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.5 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.5 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.5 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.5 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.5 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.5 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.5 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.5 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.5 sec.
Sat Dec 22 19:22:41 2018 DMAIN <0000> Transceiver.cpp:1005
[tid=3008439376] new latency: 0:204931 (underrun 3:42232 vs 1:42230)
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.5 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.5 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.6 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.6 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.6 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.6 sec.
Sat Dec 22 19:22:41 2018 DMAIN <0000> Transceiver.cpp:1005
[tid=3008439376] new latency: 0:204932 (underrun 2:42244 vs 3:42242)
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.6 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.6 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.6 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.6 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.6 sec.
Sat Dec 22 19:22:41 2018 DMAIN <0000> Transceiver.cpp:1005
[tid=3008439376] new latency: 0:204933 (underrun 1:42256 vs 2:42254)
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.6 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.6 sec.
Sat Dec 22 19:22:41 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2998391888]
Packet loss between host and device at 12858.6 sec.
^Csignal 2 received
shutting down
Sat Dec 22 19:22:41 2018 DMAIN <0000> osmo-trx.cpp:435 [tid=3025398256]
Shutting down transceiver...
Sat Dec 22 19:22:41 2018 DMAIN <0000> Transceiver.cpp:307
[tid=3025398256] Stopping the transceiver
Sat Dec 22 19:22:41 2018 DMAIN <0000> Transceiver.cpp:320
[tid=3025398256] Stopping the device
Sat Dec 22 19:22:41 2018 DMAIN <0000> Transceiver.cpp:333
[tid=3025398256] Transceiver stopped
root@orangepizero:~#
syslog at the time.....
Dec 22 19:15:01 localhost CRON[3654]: (root) CMD (command -v debian-sa1
/dev/null && debian-sa1 1 1)
Dec 22
19:17:01 localhost CRON[3677]: (root) CMD ( cd / && run-parts
--report /etc/cron.hourly)
Dec 22 19:22:21 localhost osmo-bts-trx[1576]: #033[0;m<0007> l1sap.c:510
242502/182/00/48/18 Invalid condition detected: Frame difference is
242502-242403=99 > 1!
Dec 22 19:22:42 localhost osmo-bts-trx[1576]: #033[0;m#033[1;36m<0001>
bts.c:250 Shutting down BTS 0, Reason No clock from osmo-trx
Dec 22 19:22:45 localhost osmo-bts-trx[1576]: #033[0;mShutdown timer expired
Dec 22 19:22:45 localhost osmo-bts-trx[1576]: ((*))
Dec 22 19:22:45 localhost osmo-bts-trx[1576]: |
Dec 22 19:22:45 localhost osmo-bts-trx[1576]: / \ OsmoBTS
Dec 22 19:22:45 localhost systemd[1]: osmo-bts-trx.service: Main process
exited, code=exited, status=42/n/a
Dec 22 19:22:45 localhost systemd[1]: osmo-bts-trx.service: Unit entered
failed state.
Dec 22 19:22:45 localhost systemd[1]: osmo-bts-trx.service: Failed with
result 'exit-code'.
Dec 22 19:22:47 localhost systemd[1]: osmo-bts-trx.service: Service
hold-off time over, scheduling restart.
Dec 22 19:22:47 localhost systemd[1]: Stopped Osmocom osmo-bts for osmo-trx.
Dec 22 19:22:47 localhost systemd[1]: Started Osmocom osmo-bts for osmo-trx.
Dec 22 19:22:47 localhost osmo-bts-trx[3726]: <0017> control_if.c:911
CTRL at 127.0.0.1 4238
Dec 22 19:22:47 localhost osmo-bts-trx[3726]: #033[0;m<0010>
telnet_interface.c:104 Available via telnet 127.0.0.1 4241
Dec 22 19:22:47 localhost osmo-bts-trx[3726]: #033[0;m<0012>
input/ipaccess.c:882 enabling ipaccess BTS mode, OML connecting to
127.0.0.1:3002
Dec 22 19:22:47 localhost osmo-bts-trx[3726]: #033[0;m#033[1;33m<000b>
trx_if.c:754 Open transceiver for phy0.0
Dec 22 19:22:47 localhost osmo-bts-trx[3726]: #033[0;m<0012>
input/ipa.c:128 127.0.0.1:3002 connection done
Dec 22 19:22:47 localhost osmo-bts-trx[3726]: #033[0;m<0012>
input/ipaccess.c:705 received ID get from 1801/0/0
Dec 22 19:22:47 localhost osmo-bts-trx[3726]: #033[0;m#033[1;36m<0001>
oml.c:229 O&M Get Attributes [0], Manufacturer Dependent State is
unsupported by TRX.
Dec 22 19:22:47 localhost osmo-bts-trx[3726]: #033[0;m#033[1;36m<0001>
oml.c:681 Ignoring T200[0] (150 ms) as sent by BSC due to suspected
LAPDm bug!
Dec 22 19:22:47 localhost osmo-bts-trx[3726]: #033[0;m#033[1;36m<0001>
oml.c:681 Ignoring T200[1] (180 ms) as sent by BSC due to suspected
LAPDm bug!
Dec 22 19:22:47 localhost osmo-bts-trx[3726]: #033[0;m#033[1;36m<0001>
oml.c:681 Ignoring T200[2] (180 ms) as sent by BSC due to suspected
LAPDm bug!
Dec 22 19:22:47 localhost osmo-bts-trx[3726]: #033[0;m#033[1;36m<0001>
oml.c:681 Ignoring T200[3] (1680 ms) as sent by BSC due to suspected
LAPDm bug!
Dec 22 19:22:47 localhost osmo-bts-trx[3726]: #033[0;m#033[1;36m<0001>
oml.c:681 Ignoring T200[4] (520 ms) as sent by BSC due to suspected
LAPDm bug!
Dec 22 19:22:47 localhost osmo-bts-trx[3726]: #033[0;m#033[1;36m<0001>
oml.c:681 Ignoring T200[5] (165 ms) as sent by BSC due to suspected
LAPDm bug!
Dec 22 19:22:47 localhost osmo-bts-trx[3726]: #033[0;m#033[1;36m<0001>
oml.c:681 Ignoring T200[6] (1680 ms) as sent by BSC due to suspected
LAPDm bug!
Dec 22 19:22:47 localhost osmo-bts-trx[3726]: #033[0;m#033[1;36m<0001>
oml.c:1055 ADM state already was Unlocked
Dec 22 19:22:48 localhost osmo-bts-trx[3726]: #033[0;m<0012>
input/ipa.c:128 127.0.0.1:3003 connection done
Dec 22 19:22:48 localhost osmo-bts-trx[3726]: #033[0;m<0012>
input/ipaccess.c:705 received ID get from 1801/0/0
Dec 22 19:22:49 localhost osmo-bts-trx[3726]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 19:22:51 localhost osmo-bts-trx[3726]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 19:22:53 localhost osmo-bts-trx[3726]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 19:22:55 localhost osmo-bts-trx[3726]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 22 19:22:57 localhost osmo-bts-trx[3726]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
26 Dec
26 Dec
3:28 p.m.
New subject: osmo-uhd-trx
Feedback:
I have upgraded "nightly" installation from dec-19 with the following:
replaced osmo-bts-trx_0.8.1.194.8564_armhf.deb with
osmo-bts-trx_0.8.1.199.5c93_armhf.deb
This seems to have solved the instabilities I saw and logged, I now get
just clock indications
on the trx-uhd terminal, and phones camp properly and do not loose carrier.
One remaining issue is that I have no call progress when originating
calls on MS toward
fixed network / asterisk / sip. SIP-originated calls behave normally.
tcpdump shows proper SIP messages regardless of direction. I have not
replaced
any other components, but will se which have changed 19-dec to 25-dec
and test
with them.
I hope you are having a nice Christmas, I sure have....
Gullik
27 Dec
27 Dec
9:15 a.m.
New subject: osmo-uhd-trx
I have had 100% good stability over the night. However, osmo-bts-trx
logs the following every 5-10 minutes.
There has been no "activity" nightly on the gsm network.
Gullik
Dec 27 09:08:57 localhost osmo-bts-trx[20109]: #033[0;m#033[1;35m<0000>
rsl.c:741 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN ACT ACK
Dec 27 09:09:00 localhost osmo-bts-trx[20109]: #033[0;m#033[1;35m<0000>
rsl.c:720 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN REL ACK
Dec 27 09:10:12 localhost osmo-bts-trx[20109]: #033[0;m#033[1;35m<0000>
rsl.c:741 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN ACT ACK
Dec 27 09:10:15 localhost osmo-bts-trx[20109]: #033[0;m#033[1;35m<0000>
rsl.c:720 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN REL ACK
Dec 27 09:12:03 localhost osmo-bts-trx[20109]: #033[0;m#033[1;35m<0000>
rsl.c:741 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN ACT ACK
Dec 27 09:12:03 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:920 Store content res. (dl=0xb67ec498)
Dec 27 09:12:04 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 09:12:04 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 09:12:05 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 09:12:06 localhost osmo-bts-trx[20109]: #033[0;m#033[1;35m<0000>
rsl.c:720 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN REL ACK
Dec 27 09:17:27 localhost osmo-bts-trx[20109]: #033[0;m#033[1;35m<0000>
rsl.c:741 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN ACT ACK
Dec 27 09:17:27 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:920 Store content res. (dl=0xb67ec498)
Dec 27 09:17:28 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 09:17:29 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 09:17:29 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 09:17:30 localhost osmo-bts-trx[20109]: #033[0;m#033[1;35m<0000>
rsl.c:720 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN REL ACK
Dec 27 09:32:46 localhost osmo-bts-trx[20109]: #033[0;m#033[1;35m<0000>
rsl.c:741 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN ACT ACK
Dec 27 09:32:46 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:920 Store content res. (dl=0xb67ec498)
Dec 27 09:32:48 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 09:32:48 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 09:32:48 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 09:32:49 localhost osmo-bts-trx[20109]: #033[0;m#033[1;35m<0000>
rsl.c:720 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN REL ACK
Dec 27 09:42:04 localhost osmo-bts-trx[20109]: #033[0;m#033[1;35m<0000>
rsl.c:741 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN ACT ACK
Dec 27 09:42:05 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:920 Store content res. (dl=0xb67ec498)
Dec 27 09:42:06 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 09:42:06 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 09:42:06 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 09:42:08 localhost osmo-bts-trx[20109]: #033[0;m#033[1;35m<0000>
rsl.c:720 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN REL ACK
Dec 27 09:47:32 localhost osmo-bts-trx[20109]: #033[0;m#033[1;35m<0000>
rsl.c:741 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN ACT ACK
Dec 27 09:47:32 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:920 Store content res. (dl=0xb67ec498)
Dec 27 09:47:33 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 09:47:34 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 09:47:34 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 09:47:35 localhost osmo-bts-trx[20109]: #033[0;m#033[1;35m<0000>
rsl.c:720 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN REL ACK
Dec 27 10:02:51 localhost osmo-bts-trx[20109]: #033[0;m#033[1;35m<0000>
rsl.c:741 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN ACT ACK
Dec 27 10:02:51 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:920 Store content res. (dl=0xb67ec498)
Dec 27 10:02:52 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 10:02:53 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 10:02:53 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 10:02:54 localhost osmo-bts-trx[20109]: #033[0;m#033[1;35m<0000>
rsl.c:720 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN REL ACK
7:39 p.m.
New subject: osmo-uhd-trx
Gentlemen,
While upgrading to osmo-bts-trx_0.8.1.199.5c93_armhf.deb
<http://download.opensuse.org/repositories/network:/osmocom:/nightly/Debian_9.0/armhf/osmo-bts-trx_0.8.1.199.5c93_armhf.deb>
solved most of the problem, the main
issue seems to remain. The latest version reduced failure rate from 1-3
/ hour, to 18 hours, but
did not eliminate the problem, i.e. a spinning trx-uhd. I enclose a
snippet from console:
Thu Dec 27 18:53:00 2018 DMAIN <0000> Transceiver.cpp:1005
[tid=3007431760] new latency: 7:33599 (underrun 1:1683315 vs 6:1683313)
Thu Dec 27 18:53:00 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2997609552]
Packet loss between host and device at 103454 sec.
Thu Dec 27 18:53:00 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2997609552]
Packet loss between host and device at 103454 sec.
Thu Dec 27 18:53:00 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2997609552]
Packet loss between host and device at 103454 sec.
Thu Dec 27 18:53:00 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2997609552]
Packet loss between host and device at 103454 sec.
Thu Dec 27 18:53:00 2018 DMAIN <0000> Transceiver.cpp:1005
[tid=3007431760] new latency: 7:33600 (underrun 6:1683326 vs 1:1683325)
Thu Dec 27 18:53:00 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2997609552]
Packet loss between host and device at 103454 sec.
Thu Dec 27 18:53:00 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2997609552]
Packet loss between host and device at 103454 sec.
Thu Dec 27 18:53:00 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2997609552]
Packet loss between host and device at 103454 sec.
Thu Dec 27 18:53:00 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2997609552]
Packet loss between host and device at 103454 sec.
Thu Dec 27 18:53:00 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2997609552]
Packet loss between host and device at 103454 sec.
Thu Dec 27 18:53:00 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2997609552]
Packet loss between host and device at 103454 sec.
Thu Dec 27 18:53:00 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2997609552]
Packet loss between host and device at 103454 sec.
Thu Dec 27 18:53:00 2018 DMAIN <0000> Transceiver.cpp:1005
[tid=3007431760] new latency: 7:33601 (underrun 5:1683338 vs 6:1683336)
Thu Dec 27 18:53:00 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2997609552]
Packet loss between host and device at 103454 sec.
Thu Dec 27 18:53:00 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2997609552]
Packet loss between host and device at 103454 sec.
Thu Dec 27 18:53:00 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2997609552]
Packet loss between host and device at 103454 sec.
Thu Dec 27 18:53:00 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2997609552]
Packet loss between host and device at 103454 sec.
Thu Dec 27 18:53:00 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2997609552]
Packet loss between host and device at 103454 sec.
Thu Dec 27 18:53:00 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2997609552]
Packet loss between host and device at 103454 sec.
Thu Dec 27 18:53:00 2018 DDEV <0002> UHDDevice.cpp:1319 [tid=2997609552]
Packet loss between host and device at 103454 sec.
Thu Dec 27 18:53:00 2018 DMAIN <0000> Transceiver.cpp:1005
[tid=3007431760] new latency: 7:33602 (underrun 6:1683350 vs 5:1683348)
as you can see this is very similar to running
osmo-bts-trx_0.8.1.194.8564_armhf.deb, but only happened after 18 hours
seemingly stable.
syslog says:
Dec 27 18:53:37 localhost osmo-bts-trx[2166]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 27 18:53:39 localhost osmo-bts-trx[2166]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 27 18:53:41 localhost osmo-bts-trx[2166]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
Dec 27 18:53:43 localhost osmo-bts-trx[2166]: #033[0;m#033[1;33m<000b>
trx_if.c:178 No satisfactory response from transceiver for phy0.0 (CMD
POWEROFF)
so bts-trx and trx-uhd have lost synch with each other.
Just restarting trx-uhd resolved the situation, if bts-trx had timed
out, it would have restarted, and I assume the whole thing recovered.
next time it stops, I will kill -9 bts-trx, it should restart auto, and
I will see if it does not matter WHICH process is restarted, I earlier
believed the problem was in the trx-uhd, but replacing bts-trx was the
factor to go to "almost stable".
I will report my findings, if you have any more intelligent suggestions
to how to narrow this down, please go ahead.....
Regards,
Gullik
On 2018-12-27 10:15, Gullik Webjorn wrote:
I have had 100% good stability over the night.
However, osmo-bts-trx
logs the following every 5-10 minutes.
There has been no "activity" nightly on the gsm network.
Gullik
Dec 27 09:08:57 localhost osmo-bts-trx[20109]:
#033[0;m#033[1;35m<0000> rsl.c:741
(bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN ACT ACK
Dec 27 09:09:00 localhost osmo-bts-trx[20109]:
#033[0;m#033[1;35m<0000> rsl.c:720
(bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN REL ACK
Dec 27 09:10:12 localhost osmo-bts-trx[20109]:
#033[0;m#033[1;35m<0000> rsl.c:741
(bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN ACT ACK
Dec 27 09:10:15 localhost osmo-bts-trx[20109]:
#033[0;m#033[1;35m<0000> rsl.c:720
(bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN REL ACK
Dec 27 09:12:03 localhost osmo-bts-trx[20109]:
#033[0;m#033[1;35m<0000> rsl.c:741
(bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN ACT ACK
Dec 27 09:12:03 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:920 Store content res. (dl=0xb67ec498)
Dec 27 09:12:04 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 09:12:04 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 09:12:05 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 09:12:06 localhost osmo-bts-trx[20109]:
#033[0;m#033[1;35m<0000> rsl.c:720
(bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN REL ACK
Dec 27 09:17:27 localhost osmo-bts-trx[20109]:
#033[0;m#033[1;35m<0000> rsl.c:741
(bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN ACT ACK
Dec 27 09:17:27 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:920 Store content res. (dl=0xb67ec498)
Dec 27 09:17:28 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 09:17:29 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 09:17:29 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 09:17:30 localhost osmo-bts-trx[20109]:
#033[0;m#033[1;35m<0000> rsl.c:720
(bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN REL ACK
Dec 27 09:32:46 localhost osmo-bts-trx[20109]:
#033[0;m#033[1;35m<0000> rsl.c:741
(bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN ACT ACK
Dec 27 09:32:46 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:920 Store content res. (dl=0xb67ec498)
Dec 27 09:32:48 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 09:32:48 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 09:32:48 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 09:32:49 localhost osmo-bts-trx[20109]:
#033[0;m#033[1;35m<0000> rsl.c:720
(bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN REL ACK
Dec 27 09:42:04 localhost osmo-bts-trx[20109]:
#033[0;m#033[1;35m<0000> rsl.c:741
(bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN ACT ACK
Dec 27 09:42:05 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:920 Store content res. (dl=0xb67ec498)
Dec 27 09:42:06 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 09:42:06 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 09:42:06 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 09:42:08 localhost osmo-bts-trx[20109]:
#033[0;m#033[1;35m<0000> rsl.c:720
(bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN REL ACK
Dec 27 09:47:32 localhost osmo-bts-trx[20109]:
#033[0;m#033[1;35m<0000> rsl.c:741
(bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN ACT ACK
Dec 27 09:47:32 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:920 Store content res. (dl=0xb67ec498)
Dec 27 09:47:33 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 09:47:34 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 09:47:34 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 09:47:35 localhost osmo-bts-trx[20109]:
#033[0;m#033[1;35m<0000> rsl.c:720
(bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN REL ACK
Dec 27 10:02:51 localhost osmo-bts-trx[20109]:
#033[0;m#033[1;35m<0000> rsl.c:741
(bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN ACT ACK
Dec 27 10:02:51 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:920 Store content res. (dl=0xb67ec498)
Dec 27 10:02:52 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 10:02:53 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 10:02:53 localhost osmo-bts-trx[20109]: #033[0;m<0011>
lapd_core.c:1556 N(S) sequence error: N(S)=0, V(R)=1 (dl=0xb67ec498
state LAPD_STATE_MF_EST)
Dec 27 10:02:54 localhost osmo-bts-trx[20109]:
#033[0;m#033[1;35m<0000> rsl.c:720
(bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) (ss=0) SDCCH Tx CHAN REL ACK
28 Dec
28 Dec
11:17 a.m.
A newbe find. I just deduced that call progress is PLMN based when using
osmo-msc with an external nmcc,
such as asterisk. Thus, the solution to the problem "no call progress
tones", is to modify the asterisk extensions
with a progress statement. Since msc treats mobiles just as a number of
sip clients, all calls, including
mobile - mobile are directed via the external nmcc, and in this case it
is asterisks responsibility to
generate "call progress".
I modified
exten => _07575760XX,1,Dial(SIP/GSM/${EXTEN})
to
exten => _07575760XX,1,Progress()
exten => _07575760XX,2,Dial(SIP/GSM/${EXTEN})
this did the trick....the insight gets deeper....
Gullik
2007
days inactive
2014
days old
12 comments
3 participants
participants (3)
-
Gullik Webjorn -
Harald Welte -
Tomcsányi, Domonkos