Author Topic: YateBTS freezes randomly  (Read 8288 times)

el_dorado

  • Newbie
  • *
  • Posts: 19
    • View Profile
YateBTS freezes randomly
« on: October 17, 2018, 12:45:33 PM »
Hello!

Need your help :(. I use Yate 6.1.0 and YateBTS 6.1.0 built from sources, and sometimes (often) it freezes. I attached a part of debug log. Please note the string in the log below:

Code: [Select]
2018-10-17_18:08:49.002954 <ybts-signalling:WARN> Timeout while waiting for heartbeat [0x55bc9bc266f0]
First of all, why it get timeout? Why process freezes, if it really freezes? After that YateBTS can't kill it, and restarting itself. After one or two restarts (sorry, I don't know how to get info about restarts count) it stops announce its network, and only manual 'service yate restart' helps.

Code: [Select]
-----
Primitive: L3Message
Info: 0
Connection: 516

<CC>
  <TID TIFlag="true">0</TID>
  <Message type="Disconnect">
    <Cause coding="GSM-PLMN" location="LPN">timeout</Cause>
  </Message>
</CC>
-----
2018-10-17_18:07:37.003286 <ybts/197:CALL> Hangup reason='timeout' [0x7f6cd001ea70]
2018-10-17_18:07:37.003304 <ybts/197:CALL> Destroyed [0x7f6cd001ea70]
2018-10-17_18:07:37.003526 <wave:ALL> WaveConsumer::~WaveConsumer() [0x7f6c880377b0] total=4968320 stamp=2484160
2018-10-17_18:07:37.003534 <wave:INFO> WaveConsumer rate=15988 b/s
2018-10-17_18:07:37.003560 <wave/196:ALL> WaveChan::~WaveChan() wave/196 [0x7f6c8801afc0]
2018-10-17_18:07:37.003740 <javascript:ALL> Assistant for 'ybts/197' deleted
2018-10-17_18:07:37.137213 <ybts-signalling:INFO> Received [0x55bc9bc266f0]
-----
Primitive: PhysicalInfo
Info: 0
Connection: 516

<PhysicalInfo>TA=2 TE=0.000 UpRSSI=-21 TxPwr=6 DnRSSIdBm=-80 time=1539799656.669</PhysicalInfo>
-----
2018-10-17_18:07:37.137261 <ybts-signalling:INFO> Received [0x55bc9bc266f0]
-----
Primitive: L3Message
Info: 0
Connection: 516

<CC>
  <TID TIFlag="false">0</TID>
  <NSD>1</NSD>
  <Message type="Release"/>
</CC>
-----
2018-10-17_18:07:37.137273 <ybts:NOTE> Removing terminated call 'i0' conn=516
2018-10-17_18:07:37.137278 <ybts:INFO> Call 'i0' changed state Disconnect -> Null
2018-10-17_18:07:37.137315 <ybts-signalling:INFO> Sending [0x55bc9bc266f0]
-----
Primitive: L3Message
Info: 0
Connection: 516

<CC>
  <TID TIFlag="true">0</TID>
  <Message type="ReleaseComplete">
    <Cause coding="GSM-PLMN" location="LPN">timeout</Cause>
  </Message>
</CC>
-----
2018-10-17_18:07:40.001106 <ybts-signalling:ALL> Connection 516 idle timeout [0x55bc9bc266f0]
2018-10-17_18:07:40.001130 <ybts-signalling:ALL> Releasing connection (0x7f6cd000ee20,516) [0x55bc9bc266f0]
2018-10-17_18:07:40.001156 <ybts-signalling:INFO> Sending [0x55bc9bc266f0]
-----
Primitive: ConnRelease
Info: 0
Connection: 516
-----
2018-10-17_18:07:47.001486 >>> DataTranslator::detachChain(0x7f6c88012f60,0x7f6c8801a290)
2018-10-17_18:07:47.001512   >>> DataTranslator::detachChain(0x7f6c88012f60,0x7f6c88039620)
2018-10-17_18:07:47.001522   <<< DataTranslator::detachChain
2018-10-17_18:07:47.001532   <ALL> GsmCodec::~GsmCodec() [0x7f6c88039620]
2018-10-17_18:07:47.001546 <<< DataTranslator::detachChain
2018-10-17_18:07:47.001584 <ybts/198:INFO> Call 'i0' changed state Active -> Disconnect [0x7f6cd001a380]
2018-10-17_18:07:47.001649 <ybts-signalling:INFO> Sending [0x55bc9bc266f0]
-----
Primitive: L3Message
Info: 0
Connection: 517

<CC>
  <TID TIFlag="true">0</TID>
  <Message type="Disconnect">
    <Cause coding="GSM-PLMN" location="LPN">timeout</Cause>
  </Message>
</CC>
-----
2018-10-17_18:07:47.001680 <ybts/198:CALL> Hangup reason='timeout' [0x7f6cd001a380]
2018-10-17_18:07:47.001710 <ybts/198:CALL> Destroyed [0x7f6cd001a380]
2018-10-17_18:07:47.001850 <wave:ALL> WaveConsumer::~WaveConsumer() [0x7f6c8801a290] total=4515840 stamp=2257920
2018-10-17_18:07:47.001859 <wave:INFO> WaveConsumer rate=14565 b/s
2018-10-17_18:07:47.001867 <wave/197:ALL> WaveChan::~WaveChan() wave/197 [0x7f6c88019ba0]
2018-10-17_18:07:47.002028 <javascript:ALL> Assistant for 'ybts/198' deleted
2018-10-17_18:07:48.741663 <ybts-signalling:INFO> Received [0x55bc9bc266f0]
-----
Primitive: PhysicalInfo
Info: 0
Connection: 517

<PhysicalInfo>TA=2 TE=0.000 UpRSSI=-31 TxPwr=6 DnRSSIdBm=-89 time=1539799668.694</PhysicalInfo>
-----
2018-10-17_18:07:48.741760 <ybts-signalling:INFO> Received [0x55bc9bc266f0]
-----
Primitive: L3Message
Info: 0
Connection: 517

<CC>
  <TID TIFlag="false">0</TID>
  <NSD>1</NSD>
  <Message type="Release"/>
</CC>
-----
2018-10-17_18:07:48.741785 <ybts:NOTE> Removing terminated call 'i0' conn=517
2018-10-17_18:07:48.741797 <ybts:INFO> Call 'i0' changed state Disconnect -> Null
2018-10-17_18:07:48.741890 <ybts-signalling:INFO> Sending [0x55bc9bc266f0]
-----
Primitive: L3Message
Info: 0
Connection: 517

<CC>
  <TID TIFlag="true">0</TID>
  <Message type="ReleaseComplete">
    <Cause coding="GSM-PLMN" location="LPN">timeout</Cause>
  </Message>
</CC>
-----
2018-10-17_18:07:48.861527 <ybts-signalling:INFO> Received [0x55bc9bc266f0]
-----
Primitive: L3Message
Info: 0
Connection: 517

<CC>
  <TID TIFlag="false">0</TID>
  <NSD>0</NSD>
  <Message type="Release">
    <Cause coding="GSM-PLMN" location="U">timeout</Cause>
  </Message>
</CC>
-----
2018-10-17_18:07:48.861604 <ybts-signalling:INFO> Sending [0x55bc9bc266f0]
-----
Primitive: L3Message
Info: 0
Connection: 517

<CC>
  <TID TIFlag="true">0</TID>
  <Message type="ReleaseComplete">
    <Cause coding="GSM-PLMN" location="LPN">invalid-callref</Cause>
  </Message>
</CC>
-----
2018-10-17_18:07:51.002487 <ybts-signalling:ALL> Connection 517 idle timeout [0x55bc9bc266f0]
2018-10-17_18:07:51.002504 <ybts-signalling:ALL> Releasing connection (0x7f6cd0005070,517) [0x55bc9bc266f0]
2018-10-17_18:07:51.002519 <ybts-signalling:INFO> Sending [0x55bc9bc266f0]
-----
Primitive: ConnRelease
Info: 0
Connection: 517
-----
2018-10-17_18:08:11.001069 <ybts-signalling:ALL> Removing released connection 516 [0x55bc9bc266f0]
2018-10-17_18:08:11.001107 <ybts-mm:ALL> Removed UE (0x7f6cd001c790): destroyed [0x55bc9bc1ae40]
2018-10-17_18:08:11.001121 <ybts:ALL> UE destroyed [0x7f6cd001c790]
2018-10-17_18:08:22.004833 <ybts-signalling:ALL> Removing released connection 517 [0x55bc9bc266f0]
2018-10-17_18:08:22.004862 <ybts-mm:ALL> Removed UE (0x7f6cd0023b80): destroyed [0x55bc9bc1ae40]
2018-10-17_18:08:22.004870 <ybts:ALL> UE destroyed [0x7f6cd0023b80]
2018-10-17_18:08:49.002954 <ybts-signalling:WARN> Timeout while waiting for heartbeat [0x55bc9bc266f0]
2018-10-17_18:08:49.003018 <ybts:NOTE> Peer pid 10188 has not exited - we'll kill it
2018-10-17_18:08:49.009639 <ybts:WARN> Peer pid 10188 has still not exited yet?
2018-10-17_18:08:49.070746 <ybts:WARN> Failed to kill peer pid 10188, leaving zombie
2018-10-17_18:08:49.070823 <ybts:ALL> Restart scheduled in 1ms [0x7f6cf9166500]
2018-10-17_18:08:49.070833 <ybts:ALL> Scheduled stop in 0ms
2018-10-17_18:08:49.077575 <gsmtrx:NOTE> ARFCN[0]: Missing SYNC burst at 11520704 1440088/0 T2=0 T3=1 [0x7f6cd4010580]
2018-10-17_18:08:49.125934 <gsmtrx:NOTE> ARFCN[0]: Missing SYNC burst at 11520784 1440098/0 T2=10 T3=11 [0x7f6cd4010580]
2018-10-17_18:08:49.170421 <gsmtrx:NOTE> ARFCN[0]: Missing SYNC burst at 11520864 1440108/0 T2=20 T3=21 [0x7f6cd4010580]
2018-10-17_18:08:49.216411 <gsmtrx:NOTE> ARFCN[0]: Missing SYNC burst at 11520944 1440118/0 T2=4 T3=31 [0x7f6cd4010580]
2018-10-17_18:08:49.262312 <gsmtrx:NOTE> ARFCN[0]: Missing SYNC burst at 11521024 1440128/0 T2=14 T3=41 [0x7f6cd4010580]
2018-10-17_18:08:49.312999 <gsmtrx:NOTE> ARFCN[0]: Missing SYNC burst at 11521112 1440139/0 T2=25 T3=1 [0x7f6cd4010580]
2018-10-17_18:08:49.359112 <gsmtrx:NOTE> ARFCN[0]: Missing SYNC burst at 11521192 1440149/0 T2=9 T3=11 [0x7f6cd4010580]
2018-10-17_18:08:49.405073 <gsmtrx:NOTE> ARFCN[0]: Missing SYNC burst at 11521272 1440159/0 T2=19 T3=21 [0x7f6cd4010580]
2018-10-17_18:08:49.451811 <gsmtrx:NOTE> ARFCN[0]: Missing SYNC burst at 11521352 1440169/0 T2=3 T3=31 [0x7f6cd4010580]
2018-10-17_18:08:49.497744 <gsmtrx:NOTE> ARFCN[0]: Missing SYNC burst at 11521432 1440179/0 T2=13 T3=41 [0x7f6cd4010580]
2018-10-17_18:08:49.548408 <gsmtrx:NOTE> ARFCN[0]: Missing SYNC burst at 11521520 1440190/0 T2=24 T3=1 [0x7f6cd4010580]
2018-10-17_18:08:49.594508 <gsmtrx:NOTE> ARFCN[0]: Missing SYNC burst at 11521600 1440200/0 T2=8 T3=11 [0x7f6cd4010580]
2018-10-17_18:08:49.640505 <gsmtrx:NOTE> ARFCN[0]: Missing SYNC burst at 11521680 1440210/0 T2=18 T3=21 [0x7f6cd4010580]
2018-10-17_18:08:49.687191 <gsmtrx:NOTE> ARFCN[0]: Missing SYNC burst at 11521760 1440220/0 T2=2 T3=31 [0x7f6cd4010580]
2018-10-17_18:08:49.733134 <gsmtrx:NOTE> ARFCN[0]: Missing SYNC burst at 11521840 1440230/0 T2=12 T3=41 [0x7f6cd4010580]
2018-10-17_18:08:49.783804 <gsmtrx:NOTE> ARFCN[0]: Missing SYNC burst at 11521928 1440241/0 T2=23 T3=1 [0x7f6cd4010580]
2018-10-17_18:08:49.829949 <gsmtrx:NOTE> ARFCN[0]: Missing SYNC burst at 11522008 1440251/0 T2=7 T3=11 [0x7f6cd4010580]
2018-10-17_18:08:49.875855 <gsmtrx:NOTE> ARFCN[0]: Missing SYNC burst at 11522088 1440261/0 T2=17 T3=21 [0x7f6cd4010580]
2018-10-17_18:08:49.922636 <gsmtrx:NOTE> ARFCN[0]: Missing SYNC burst at 11522168 1440271/0 T2=1 T3=31 [0x7f6cd4010580]
2018-10-17_18:08:49.968585 <gsmtrx:NOTE> ARFCN[0]: Missing SYNC burst at 11522248 1440281/0 T2=11 T3=41 [0x7f6cd4010580]
2018-10-17_18:08:50.001874 <ybts/199:INFO> Call 'i0' changed state Active -> Disconnect [0x7f6cd001b6b0]
2018-10-17_18:08:50.001967 <ybts-signalling:INFO> Sending [0x55bc9bc266f0]
-----
Primitive: L3Message
Info: 0
Connection: 519

<CC>
  <TID TIFlag="true">0</TID>
  <Message type="Disconnect">
    <Cause coding="GSM-PLMN" location="LPN">interworking</Cause>
  </Message>
</CC>
-----
2018-10-17_18:08:50.002006 <ybts-signalling:WARN> Socket send error: 111 Connection refused [0x55bc9bc266f0]
2018-10-17_18:08:50.002045 <ybts/199:CALL> Hangup reason='interworking' [0x7f6cd001b6b0]
2018-10-17_18:08:50.002078 >>> DataTranslator::detachChain(0x7f6c88038b60,0x7f6c88003f10)
2018-10-17_18:08:50.002087   >>> DataTranslator::detachChain(0x7f6c88038b60,0x7f6c88022a60)
2018-10-17_18:08:50.002095   <<< DataTranslator::detachChain
2018-10-17_18:08:50.002103   <ALL> GsmCodec::~GsmCodec() [0x7f6c88022a60]
2018-10-17_18:08:50.002115 <<< DataTranslator::detachChain
2018-10-17_18:08:50.002146 <ybts/199:CALL> Destroyed [0x7f6cd001b6b0]
2018-10-17_18:08:50.002184 <ybts/200:INFO> Call 'i0' changed state Active -> Disconnect [0x7f6cd001b260]
2018-10-17_18:08:50.002242 <ybts-signalling:INFO> Sending [0x55bc9bc266f0]
-----
Primitive: L3Message
Info: 0
Connection: 524

<CC>
  <TID TIFlag="true">0</TID>
  <Message type="Disconnect">
    <Cause coding="GSM-PLMN" location="LPN">interworking</Cause>
  </Message>
</CC>
-----
2018-10-17_18:08:50.002262 <ybts-signalling:WARN> Socket send error: 107 Transport endpoint is not connected [0x55bc9bc266f0]
2018-10-17_18:08:50.002304 <ybts/200:CALL> Hangup reason='interworking' [0x7f6cd001b260]
2018-10-17_18:08:50.002343 >>> DataTranslator::detachChain(0x7f6c8802e040,0x7f6c88028f60)
2018-10-17_18:08:50.002356   >>> DataTranslator::detachChain(0x7f6c8802e040,0x7f6c88003d10)
2018-10-17_18:08:50.002367   <<< DataTranslator::detachChain
2018-10-17_18:08:50.002377   <ALL> GsmCodec::~GsmCodec() [0x7f6c88003d10]
2018-10-17_18:08:50.002392 <<< DataTranslator::detachChain
2018-10-17_18:08:50.002430 <ybts/200:CALL> Destroyed [0x7f6cd001b260]
2018-10-17_18:08:50.002475 <ybts/201:INFO> Call 'i0' changed state Active -> Disconnect [0x7f6cd001d920]
2018-10-17_18:08:50.002571 <ybts-signalling:INFO> Sending [0x55bc9bc266f0]
-----
Primitive: L3Message
Info: 0
Connection: 525

<CC>
  <TID TIFlag="true">0</TID>
  <Message type="Disconnect">
    <Cause coding="GSM-PLMN" location="LPN">interworking</Cause>
  </Message>
</CC>
-----

el_dorado

  • Newbie
  • *
  • Posts: 19
    • View Profile
Re: YateBTS freezes randomly
« Reply #1 on: October 18, 2018, 09:48:27 AM »
Update: new issues when this happens, it has the network visible but cannot join it.

marian

  • Hero Member
  • *****
  • Posts: 513
    • View Profile
Re: YateBTS freezes randomly
« Reply #2 on: October 18, 2018, 11:50:43 PM »
Please attach more log before heartbeat timeout.

el_dorado

  • Newbie
  • *
  • Posts: 19
    • View Profile
Re: YateBTS freezes randomly
« Reply #3 on: October 19, 2018, 05:19:53 AM »
marian,
Please see the attached log and please tell if you need more lengthy log or more detailed (currently "-vvvv"). The log was stripped from sensitive data replacing it with zeroes.