Logging
YateBTS uses its own logging mechanism. To make use of it, you need to specify the log destination file before starting Yate.
Example:
The command below informs Yate to start as a supervised daemon and to log the output into the specified file.
yate -sd -vvv -l /var/log/
The -s starts Yate supervised, and -d as a daemon. The -v sets the verbosity level. For more information, go to the Set the debugging level section below.
logrotate
YateBTS also uses logrotate, a UNIX program that eases the management of log files by automatically compressing, rotating, removing and emailing the logs as specified in the configuration. It runs as a daily cron job. Yate does not rotate its own logs, but integrates them into logrotate by providing a configuration file for it.
When you install Yate as a service, this file will be installed as /etc/logrotate.d/yate/, along with the configuration files for all the other services and programs installed on your system.
Type:
man logrotate
in the command line for an explanation of logrotate options and configuration file syntax.
To use yate.logrotate, you must enable the rotate option when you start Yate as a service. The -r option requires enabling the supervised mode and naming a log file. Run Yate including -s -r -l to the command yate.
When running Yate as a service with rotation enabled, you will find the log files in var/log/yate. Otherwise, the log files are found in the build directory. For more information related to Yate’s start command, type yate –help.
Copy packing/yate.logrotate as /etc/logrotate.d/yate and optionally edit it to adjust the limits. Note that logrotate normally runs daily so make sure you collect significantly less than 2GB of logs in 24 hours.
You will also need to make the file owned by root:
cp packing/yate.logrotate /etc/logrotate.d/yate
chown root.root /etc/logrotate.d/yate
If your log files grow too fast you have to either reduce the logging level – eventually per module – or set up logrotate to run more often. For example, you can move the logrotate script from /etc/cron.daily to /etc/cron.hourly. For more information go to: Logrotate in Yate.
Here are some typical logging settings that you will use more frequently in YateBTS’ Telnet:
mbts rawconfig Log.Level.GSML2LAPDm.cpp INFO – for an L2 trace
mbts rawconfig Log.Level.RadioResource.cpp INFO – for an L3 RR trace
mbts rawconfig Log.Level.NeighborTable.cpp
mbts rawconfig Log.Level.TRXManager.cpp
transceiver
Since it runs in a separate process the transceiver logs and debug messages are piped to the ybts module.
If no transceiver logs or debug messages are displayed but the transceiver otherwise appears to work see how to restart transceiver to fix this condition.
Debugging
Set timestamp
We strongly recommend you set up the timestamp of the debugging messages to the local time of machine running YateBTS. To do so, run the following command, with the -Dz option:
yate -sd -vvv -l /var/log/ -Dz
Set the debugging level
The command below allows you to set Yate’s debugging level, by adding or removing the number of -v(s):
yate -sd -vvvvv -l /var/log/
Note: Depending on the number of -v(s) you select, you can see different debugging messages:
See a more detailed list of debugging levels in the next Note.
To increase the debug level in Telnet, run the command:
debug mbts level 10
Note: There are 11 debugging levels: DebugFail = 0, DebugTest = 1, DebugGoOn = 2, DebugConf = 3, DebugStub = 4, DebugWarn = 5, DebugMild = 6, DebugCall = 7, DebugNote = 8, DebugInfo = 9, DebugAll = 10.
To adjust the transceiver debug level in Telnet:
debug transceiver level 10
Telnet debugging commands
To print the messages exchanged between the Yate modules run the following command in Telnet:
sniffer on
Other useful Telnet commands are:
debug on
prints Yate debugging messages
color on
prints the messages colored
output on
prints output messages.
Example
Below is a basic example of enabling debugging on mbts, ybts, sip – level 10 (the maximum level).
Start the sniffer and add a filter for user.register.
These are the commands and their results in Telnet:
debug mbts level 10
Module mbts debug on level 10
debug ybts level 10
Module ybts debug on level 10 objects off
sniffer on
Message sniffer: on, timer: off
sniffer filter user.register
Message sniffer: on, timer: off, filter: user.register
debug sip level 10
Module sip debug on level 10 objects off
See some snippets from the log below. You will see messages from MBTS, the part that handles the radio. The received information reaches the YBTS module that makes the translation to Yate messages (user.register).
Yate messages are handled by the application layer (nib.js or roaming.js).
In this example, roaming.js handles the user.register message. It then sends another Yate message, handled by the SIP module that forwards registration requests to the MSC/VLR. The SIP module receives the answer, which is then handled in the application layer (roaming.js).
Afterwards, roaming.js answers to the original user.register message. You can then see the messages in the YBTS and MBTS modules when the answer is about to be sent back to the phone.
The example presents only the first part of the registration process (the use of 2G authentication). This is a proof of concept and a significant part of the logs and messages was stripped.
20140814133327.093530 RadioResource.cpp:167:AccessGrantResponder:
**Incoming Burst** lur=1 gprs=0 when=0:499001 age=5 TE=1.44141 RSSI=-3 RA=0x1
.
.
.
20140814133327.432721 Received [0x1b1b360]
—–
BUFFER: 00 00 00 65 05 08 02 00 f1 09 03 e9 33 05 f4 00 7b 00 f4
Primitive: L3Message
Info: 0
Connection: 101
0
0
false
IMSI-attach
0
00190
03e9
class4
GSM-phase2
ES-IND
007b00f4
—–
.
.
.
20140814133327.432811 Sending [0x1b1b360]
—–
BUFFER: 00 00 00 65 05 18 02
Primitive: L3Message
Info: 0
Connection: 101
IMEI
—–
.
.
.
20140814133328.374098 Received [0x1b1b360]
—–
BUFFER: 00 00 00 65 05 59 08 3a 15 77 01 45 63 65 09
Primitive: L3Message
Info: 0
Connection: 101
0
1
351771054365690
—–
20140814133328.374181 Started location updating thread for
(0x7f1554002a90) TMSI=007b00f4 IMSI= [0x7f1554001a80]
Sniffed ‘user.register’ time=1408012408.374173
thread=0x7f1554001a80 ‘YBTSLocUpd’
data=(nil)
retval='(null)’
param[‘phy_info’] = ‘TA=1 TE=0.371 UpRSSI=-3 TxPwr=39 DnRSSIdBm=-48
time=1408012408.120′
param[‘driver’] = ‘ybts’
param[‘tmsi’] = ‘007b00f4’
param[‘imei’] = ‘351771054365690’
.
.
.
20140814133328.374443 Preparing to send REGISTER imsi=,
tmsi=’007b00f4′, unresponsive server=
20140814133328.374610 Entered getSIPRegistrar()
tmsi=’007b00f4′, nnsf_mask=
.
.
.
20140814133328.376517 <sip:INFO> ‘udp:0.0.0.0:5060’ sending ‘REGISTER
sip:192.168.168.245:5058′ 0x7f155802ef00 to 192.168.168.245:5058 [0x1a67c10]
——
REGISTER sip:192.168.168.245:5058 SIP/2.0
Max-Forwards: 20
From: <sip:IMSI001010000000001@192.168.168.245:5058>;tag=899988055
To: <sip:IMSI001010000000001@192.168.168.245:5058>
Contact: <sip:IMSI001010000000001@192.168.168.168>;expires=3600
+sip.instance=”<urn:gsma:imei:35177105-436569-0>”
Expires: 3600
P-Access-Network-Info: 3GPP-GERAN;cgi-3gpp=0019003e9000b;
gstn-location=”40740123456″
P-PHY-Info: YateBTS;TA=1 TE=0.371 UpRSSI=-3 TxPwr=39
DnRSSIdBm=-48 time=1408012408.120
Via: SIP/2.0/UDP 192.168.168.168:5060;rport;branch=z9hG4bK1326141354
Call-ID: 252511161@192.168.168.168
CSeq: 129 REGISTER
User-Agent: YateBTS/3.1.3
Allow: ACK, INVITE, BYE, CANCEL, MESSAGE, REGISTER, INFO, OPTIONS
Content-Length: 0
——
20140814133328.418488 <sip:INFO> ‘udp:0.0.0.0:5060’ received 503 bytes SIP
message from 192.168.168.245:5058 [0x1a67c10]
——
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.168.168:5060;rport=5060;branch=z9hG4bK1326141354;
received=192.168.168.168
From: <sip:IMSI001010000000001@192.168.168.245:5058>;tag=899988055
To: <sip:IMSI001010000000001@192.168.168.245:5058>
Call-ID: 252511161@192.168.168.168
CSeq: 129 REGISTER
WWW-Authenticate: Digest realm=”SIM”, nonce=”S07bdz10KVkrXrK+MvN1tw==”,
algorithm=AKAv1-MD5
Server: YATE/5.4.1
Allow: ACK, INVITE, BYE, CANCEL, REGISTER, OPTIONS, INFO, MESSAGE
Content-Length: 0
——
20140814133328.422146 <sip:ALL> YateSIPGenerate got answer 401 [0x7f15933cf620]
Returned false ‘user.register’ delay=0.051905
thread=0x7f1554001a80 ‘YBTSLocUpd’
data=(nil)
retval='(null)’
param[‘phy_info’] = ‘TA=1 TE=0.371 UpRSSI=-3 TxPwr=39 DnRSSIdBm=-48
time=1408012408.120′
param[‘driver’] = ‘ybts’
param[‘tmsi’] = ‘007b00f4’
param[‘imei’] = ‘351771054365690’
param[‘handlers’] = ‘monitoring:1,regexroute:10,roaming:80,regfile:100’
param[‘imsi’] = ‘001010000000001’
param[‘assoc_server’] = ‘192.168.168.245:5058’
param[‘auth.rand’] = ‘4b4edb773d7429592b5eb2be32f375b7’
param[‘error’] = ‘noauth’
20140814133328.426154 Sending [0x1b1b360]
—–
BUFFER: 00 00 00 65 05 12 00 4b 4e db 77 3d 74 29 59 2b 5e b2 be 32 f3 75 b7
Primitive: L3Message
Info: 0
Connection: 101
0
4b4edb773d7429592b5eb2be32f375b7
—–
.
.
.