Logging and Debugging

From YateBTS
Jump to: navigation, search

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/<name.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/<name.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/<name.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 <mbts:INFO> RadioResource.cpp:167:AccessGrantResponder:
**Incoming Burst** lur=1 gprs=0 when=0:499001 age=5 TE=1.44141 RSSI=-3 RA=0x1
.
.
.
20140814133327.432721 <ybts-signalling:INFO> 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

<MM>
  <SkipIndicator>0</SkipIndicator>
  <NSD>0</NSD>
  <Message type="LocationUpdatingRequest">
    <LocationUpdatingType>
      <FOR>false</FOR>
      <LUT>IMSI-attach</LUT>
    </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>
  <SkipIndicator>0</SkipIndicator>
  <NSD>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>
   <rand>4b4edb773d7429592b5eb2be32f375b7</rand>
 </Message>
</MM>
-----
.
.
.