Logging and Debugging

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.

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:


 * no -v - prints debugging messages from DebugFail to DebugWarn (0-5)
 * -v - prints debugging messages from DebugFail to DebugMild (0-6)
 * -vv - prints debugging messages from DebugFail to DebugCall (0-7)
 * -vvv - prints debugging messages from DebugFail to DebugNote (0-8)
 * -vvvv - prints debugging messages from DebugFail to DebugInfo (0-9)
 * -vvvvv - prints debugging messages from DebugFail to DebugAll (0-10)

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 </LocationUpdatingType> <CipheringKeySequenceNumber>0</CipheringKeySequenceNumber> <LAI> <PLMNidentity>00190</PLMNidentity> <LAC>03e9</LAC> </LAI> <MobileStationClassmark> <RFPowerCapability>class4</RFPowerCapability> <RevisionLevel>GSM-phase2</RevisionLevel> <Flags>ES-IND</Flags> </MobileStationClassmark> <MobileIdentity> <TMSI>007b00f4</TMSI> </MobileIdentity> </Message> </MM> - . . . 20140814133327.432811 <ybts-signalling:INFO> Sending [0x1b1b360] - BUFFER: 00 00 00 65 05 18 02 Primitive: L3Message Info: 0 Connection: 101 <MM> <Message type="IdentityRequest"> <IdentityType>IMEI</IdentityType> </Message> </MM> - . . . 20140814133328.374098 <ybts-signalling:INFO> Received [0x1b1b360] - BUFFER: 00 00 00 65 05 59 08 3a 15 77 01 45 63 65 09 Primitive: L3Message Info: 0 Connection: 101 <MM> 0</SkipIndicator> 1</NSD> <Message type="IdentityResponse"> <MobileIdentity> <IMEI>351771054365690</IMEI> </MobileIdentity> </Message> </MM> - 20140814133328.374181 <ybts:ALL> 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 <roaming:INFO> Preparing to send REGISTER imsi='', tmsi='007b00f4', unresponsive server='' 20140814133328.374610 <roaming:INFO> 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 <ybts-signalling:INFO> 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 <MM> <Message type="AuthenticationRequest"> <CipheringKeySequenceNumber>0</CipheringKeySequenceNumber> 4b4edb773d7429592b5eb2be32f375b7 </Message> </MM> - . ..