GPRS Issues

[iedemam]

There are multiple issues being reported regarding GPRS reliability in 5.0. This is a general ticket to collect notes and see if there are commonalities.

[dchard]

The GPRS issue is two fold:

1. Related to GPRS Timer ID: T3180.
2. Related to GPRS Timer ID: T3168.

With both issues the MS side symptoms are completely unstable working of the GPRS connection: during constant ping there is one packet with very high latency (2-3000ms compared to the avergae value of 3-400ms before and after), or multiple packets lost. 50% of the time this behavior is limited to 1-2-3 packets (or ICMP requests), but 50% of the time the only way to get out uf this is by deactivating the PDP context and reactivate it.

Please see the detailed logs of each issue in the following posts.

[dchard]

Related to GPRS Timer ID: T3180.

This usually happens during an already successfully activated PDP context, when there is active data transfer present. The MS can usually get out of this fast and can continue the session.

Here is a short log of what happens from the MS point of view:

EVENT EVENT_GPRS_PACKET_DOWNLINK_ASSIGNMENT14:39:47.463 Time Slot Allocation: 112, TFI Assignment: 28 EVENT EVENT_GPRS_MAC_MSG_SENT 14:39:47.463 Message: Packet Control Acknowledgement Channel: 0 EVENT EVENT_GPRS_MAC_MSG_SENT 14:39:47.629 Message: Packet Downlink Ack/Nack Channel: 0 EVENT EVENT_GPRS_MAC_MSG_RECEIVED 14:39:47.725 Message: Packet Uplink Ack/Nack Channel: 0 EVENT EVENT_GPRS_MAC_MSG_SENT 14:39:47.725 Message: Packet Control Acknowledgement Channel: 0 EVENT EVENT_GPRS_TBF_RELEASE 14:39:48.156 TBF Release Type: DL_TBF_NORMAL EVENT EVENT_GPRS_MAC_MSG_SENT 14:39:50.045 Message: Packet Measurement Report Channel: 0

!!! ERROR EVENT !!!

EVENT EVENT_GPRS_TIMER_EXPIRY 14:39:53.003 GPRS Timer ID: T3180 EVENT EVENT_GPRS_TBF_RELEASE 14:39:53.003 TBF Release Type: UL_TBF_ABNORMAL EVENT EVENT_GSM_L1_STATE 14:39:53.015 L1_IDLE_MODE EVENT EVENT_GSM_L1_STATE 14:39:53.024 L1_RANDOM_ACCESS_MODE EVENT EVENT_RANDOM_ACCESS_REQUEST 14:39:53.032 1 31601 GMAC_ONE_PHASE_ACCESS EVENT EVENT_GSM_MESSAGE_RECEIVED 14:39:53.212 IMMEDIATE_ASSIGNMENT EVENT EVENT_GPRS_MAC_MSG_SENT 14:39:53.213 Message: Packet Resource Request Channel: 0 EVENT EVENT_GPRS_PACKET_RESOURCE_REQUEST14:39:53.213 Access Type: 0 EVENT EVENT_GSM_L1_STATE 14:39:53.226 L1_TRANSFER_MODE EVENT EVENT_GPRS_TIMER_EXPIRY 14:39:56.237 GPRS Timer ID: T3168 EVENT EVENT_GPRS_TBF_RELEASE 14:39:56.237 TBF Release Type: UL_TBF_ABNORMAL EVENT EVENT_GSM_L1_STATE 14:39:56.260 L1_IDLE_MODE EVENT EVENT_GSM_L1_STATE 14:39:56.268 L1_RANDOM_ACCESS_MODE EVENT EVENT_RANDOM_ACCESS_REQUEST 14:39:56.277 1 32304 GMAC_ONE_PHASE_ACCESS EVENT EVENT_GSM_MESSAGE_RECEIVED 14:39:56.508 IMMEDIATE_ASSIGNMENT

After some RACH tries the MS can get back to normal operation:

EVENT EVENT_GSM_L1_STATE 14:40:11.568 L1_RANDOM_ACCESS_MODE EVENT EVENT_RANDOM_ACCESS_REQUEST 14:40:11.577 1 35619 GMAC_ONE_PHASE_ACCESS EVENT EVENT_GSM_MESSAGE_RECEIVED 14:40:11.808 IMMEDIATE_ASSIGNMENT EVENT EVENT_GPRS_MAC_MSG_SENT 14:40:11.808 Message: Packet Resource Request Channel: 0 EVENT EVENT_GPRS_PACKET_RESOURCE_REQUEST14:40:11.808 Access Type: 0 EVENT EVENT_GSM_L1_STATE 14:40:11.826 L1_TRANSFER_MODE EVENT EVENT_GPRS_TIMER_EXPIRY 14:40:14.837 GPRS Timer ID: T3168 EVENT EVENT_GPRS_TBF_RELEASE 14:40:14.837 TBF Release Type: UL_TBF_ABNORMAL EVENT EVENT_GSM_L1_STATE 14:40:14.860 L1_IDLE_MODE EVENT EVENT_GSM_MESSAGE_RECEIVED 14:40:15.094 IMMEDIATE_ASSIGNMENT EVENT EVENT_GPRS_MAC_MSG_SENT 14:40:15.095 Message: Packet Control Acknowledgement Channel: 0 EVENT EVENT_GSM_L1_STATE 14:40:15.306 L1_TRANSFER_MODE EVENT EVENT_GPRS_TBF_RELEASE 14:40:20.322 TBF Release Type: DL_TBF_ABNORMAL EVENT EVENT_GSM_L1_STATE 14:40:20.338 L1_IDLE_MODE EVENT EVENT_GSM_MESSAGE_RECEIVED 14:40:21.214 IMMEDIATE_ASSIGNMENT EVENT EVENT_GPRS_MAC_MSG_SENT 14:40:21.215 Message: Packet Control Acknowledgement Channel: 0 EVENT EVENT_GSM_L1_STATE 14:40:21.426 L1_TRANSFER_MODE

!!! GPRS returns to normal operation !!!

EVENT EVENT_GPRS_MAC_MSG_RECEIVED 14:40:21.566 Message: Packet Downlink Assignment Channel: 0 EVENT EVENT_GPRS_PACKET_DOWNLINK_ASSIGNMENT14:40:21.566 Time Slot Allocation: 112, TFI Assignment: 31 EVENT EVENT_GPRS_MAC_MSG_SENT 14:40:21.566 Message: Packet Control Acknowledgement Channel: 0 EVENT EVENT_GPRS_MAC_MSG_SENT 14:40:21.768 Message: Packet Downlink Ack/Nack Channel: 0 EVENT EVENT_GPRS_MAC_MSG_SENT 14:40:22.087 Message: Packet Downlink Ack/Nack Channel: 0 EVENT EVENT_GPRS_MAC_MSG_RECEIVED 14:40:22.202 Message: Packet Uplink Assignment Channel: 0 EVENT EVENT_GPRS_PACKET_UPLINK_ASSIGNMENT14:40:22.203 Time Slot Allocation: 48, Coding Scheme: 0

This issue is quite infrequent, and probably related to the second one, which I will describe in the following post.

[dchard]

Related to GPRS Timer ID: T3168.

This issue is usually present during:

• PDP cotext activation
• During an active GPRS session when the MS is coming back from IDLE with RACH

The easiest way to reproduce is to send one ping than wait 5-6 seconds and send another one. The lot of RACH and context switching will bring this error up very fast.

Problem description:

1. During PDP CA: the PDP context setup time is signifficantly higher, it can even take 4-6-10 seconds or more. In some of the cases it was impossible to activate the PDP context.
2. During transfer: the MS loses the connectivity but not the PDP context. You can see this eg. when a constant pinging is actually starts producing lost packets, or an active FTP/SCP transfer is getting disconnected.

The interesting part is during the erroneous operation, the MS shows 4 UL TS utilization when only 2 UL TS is allocated in the BTS configuration (and 3 DL TS). 100% on the time when the problem arises, the MS shows this symptom. The picture below shows the MS getting in a loop producing this 4 UL TS alloc which should not be possible:

The MS side log of the issue you can see on the previous picture:

EVENT EVENT_GPRS_PACKET_RESOURCE_REQUEST 16:19:05.856 Access Type: 0 EVENT EVENT_GSM_L1_STATE 16:19:05.869 L1_TRANSFER_MODE EVENT EVENT_GPRS_TIMER_EXPIRY 16:19:08.879 GPRS Timer ID: T3168 EVENT EVENT_GPRS_TBF_RELEASE 16:19:08.880 TBF Release Type: UL_TBF_ABNORMAL EVENT EVENT_GSM_L1_STATE 16:19:08.902 L1_IDLE_MODE EVENT EVENT_GSM_L1_STATE 16:19:08.911 L1_RANDOM_ACCESS_MODE EVENT EVENT_RANDOM_ACCESS_REQUEST 16:19:08.920 1 6651 GMAC_ONE_PHASE_ACCESS EVENT EVENT_GSM_MESSAGE_RECEIVED 16:19:09.150 IMMEDIATE_ASSIGNMENT EVENT EVENT_GPRS_MAC_MSG_SENT 16:19:09.151 Message: Packet Control Acknowledgement Channel: 0 EVENT EVENT_GSM_MESSAGE_RECEIVED 16:19:09.339 IMMEDIATE_ASSIGNMENT EVENT EVENT_GSM_L1_STATE 16:19:09.349 L1_TRANSFER_MODE EVENT EVENT_GPRS_TBF_RELEASE 16:19:14.364 TBF Release Type: DL_TBF_ABNORMAL EVENT EVENT_GSM_L1_STATE 16:19:14.376 L1_IDLE_MODE EVENT EVENT_GSM_L1_STATE 16:19:14.385 L1_RANDOM_ACCESS_MODE EVENT EVENT_RANDOM_ACCESS_REQUEST 16:19:14.393 1 7837 GMAC_ONE_PHASE_ACCESS EVENT EVENT_GSM_MESSAGE_RECEIVED 16:19:14.564 IMMEDIATE_ASSIGNMENT EVENT EVENT_GPRS_MAC_MSG_SENT 16:19:14.569 Message: Packet Resource Request Channel: 0 EVENT EVENT_GPRS_PACKET_RESOURCE_REQUEST 16:19:14.569 Access Type: 0 EVENT EVENT_GSM_L1_STATE 16:19:14.587 L1_TRANSFER_MODE EVENT EVENT_GPRS_TIMER_EXPIRY 16:19:17.598 GPRS Timer ID: T3168 EVENT EVENT_GPRS_TBF_RELEASE 16:19:17.598 TBF Release Type: UL_TBF_ABNORMAL EVENT EVENT_GSM_L1_STATE 16:19:17.621 L1_IDLE_MODE EVENT EVENT_GSM_L1_STATE 16:19:17.629 L1_RANDOM_ACCESS_MODE EVENT EVENT_RANDOM_ACCESS_REQUEST 16:19:17.638 1 8540 GMAC_ONE_PHASE_ACCESS EVENT EVENT_GSM_MESSAGE_RECEIVED 16:19:17.859 IMMEDIATE_ASSIGNMENT EVENT EVENT_GPRS_MAC_MSG_SENT 16:19:17.860 Message: Packet Resource Request Channel: 0 EVENT EVENT_GPRS_PACKET_RESOURCE_REQUEST 16:19:17.860 Access Type: 0 EVENT EVENT_GSM_L1_STATE 16:19:17.869 L1_TRANSFER_MODE EVENT EVENT_GPRS_TIMER_EXPIRY 16:19:20.879 GPRS Timer ID: T3168 EVENT EVENT_GPRS_TBF_RELEASE 16:19:20.880 TBF Release Type: UL_TBF_ABNORMAL EVENT EVENT_GSM_L1_STATE 16:19:20.902 L1_IDLE_MODE EVENT EVENT_GSM_L1_STATE 16:19:20.911 L1_RANDOM_ACCESS_MODE

You can see that after T3168 timeout the MS releases the TBF with UL_TBF_ABNORMAL, and tries to RACH as per the GSM spec. requires it to do, but it never receives a Packet Uplink Assignment.

TODO:

Try and verify through a BTS Wireshark log if the BTS actually send the missing Packet Uplink Assignment to the MS or not. If it tries to send it, maybe the problem is related to the audio dropout issue already being worked on, or some general low layer problem (TRX, UHD)?

Details:

Test conducted with OpenBTS 5 latest master and Ettus B200 with latest stable UHD driver (3.8.0). OpenBTS was set to 3 PDCH and a maximum of 2 UL and 3 DL TS with only one MS being connected to the BTS at any given time.

The problems were reproduced by 3 different MSs, all of them also tested on commercial 2G network and it was not possible to reproduce these issues with them on the commercial network.

[iedemam]

Thanks, @dchard!

A note for further reports, do please include which radio hardware this is running on and if your setup is virtualized or not. These are important factors.

[dchard]

Hi Michael,

The radio is an Ettus B200 with UHD 3.8.0. The environment is non-virtualized Core I7 with 32bit Ubuntu 14.04 LTS server, the B200 is using USB3. I also tried with a duplex filter but it did not changed anything.

Can you enable the possibility to upload and attach text files? I have some detialed logs but it is a lot of text to just copy and paste it here.

Regards, Csaba

[dchard]

Adding to T3168 ralted part:

During the erroneous operation the "gprs list" command gives this same output for seconds:

MS#1,TLLI=c0069001,800b8002 rrmode=PacketIdle Bytes:194677up/546547down Utilization=0%

This somehwat proves that the packet uplink assignment is probabny not even sent by openbts (and not get lost on lower layers), otherwise the RRmode should change to PacketTransfer.

Question:

maybe the packet resource request is not reaching the BTS, and this is why it never tries to send a packet uplink assignment?

Regards, Csaba

[dchard]

Note: with UHD 003.008.001 the same problems are still exists.

[dchard]

The following results were generated by a script that does one ping in every 6 seconds and it forces the MS to go from IDLE to CONNECTED to IDLE every 6 seconds.

As you can see, sometimes it takes quite some time to reproduce the GPRS related issue, but it is still there:

Here is the log for the erroneous part:

EVENT EVENT_GPRS_TBF_RELEASE 11:10:18.948 TBF Release Type: UL_TBF_NORMAL EVENT EVENT_GSM_L1_STATE 11:10:19.040 L1_IDLE_MODE EVENT EVENT_GSM_L1_STATE 11:10:21.144 L1_RANDOM_ACCESS_MODE EVENT EVENT_RANDOM_ACCESS_REQUEST 11:10:21.185 1 13407 GMAC_ONE_PHASE_ACCESS EVENT EVENT_GSM_MESSAGE_RECEIVED 11:10:21.305 IMMEDIATE_ASSIGNMENT EVENT EVENT_GPRS_MAC_MSG_SENT 11:10:21.306 Message: Packet Resource Request Channel: 0 EVENT EVENT_GPRS_PACKET_RESOURCE_REQUEST 11:10:21.306 Access Type: 0 EVENT EVENT_GSM_L1_STATE 11:10:21.309 L1_TRANSFER_MODE EVENT EVENT_GPRS_TIMER_EXPIRY 11:10:24.320 GPRS Timer ID: T3168 EVENT EVENT_GPRS_TBF_RELEASE 11:10:24.320 TBF Release Type: UL_TBF_ABNORMAL EVENT EVENT_GSM_L1_STATE 11:10:24.343 L1_IDLE_MODE EVENT EVENT_GSM_L1_STATE 11:10:24.351 L1_RANDOM_ACCESS_MODE EVENT EVENT_RANDOM_ACCESS_REQUEST 11:10:24.360 1 14095 GMAC_ONE_PHASE_ACCESS EVENT EVENT_GSM_MESSAGE_RECEIVED 11:10:24.600 IMMEDIATE_ASSIGNMENT EVENT EVENT_GPRS_MAC_MSG_SENT 11:10:24.601 Message: Packet Resource Request Channel: 0 EVENT EVENT_GPRS_PACKET_RESOURCE_REQUEST 11:10:24.601 Access Type: 0 EVENT EVENT_GSM_L1_STATE 11:10:24.609 L1_TRANSFER_MODE EVENT EVENT_GPRS_TIMER_EXPIRY 11:10:27.620 GPRS Timer ID: T3168 EVENT EVENT_GPRS_TBF_RELEASE 11:10:27.620 TBF Release Type: UL_TBF_ABNORMAL EVENT EVENT_GSM_L1_STATE 11:10:27.643 L1_IDLE_MODE EVENT EVENT_GSM_L1_STATE 11:10:27.652 L1_RANDOM_ACCESS_MODE EVENT EVENT_RANDOM_ACCESS_REQUEST 11:10:27.660 1 14810 GMAC_ONE_PHASE_ACCESS EVENT EVENT_GSM_MESSAGE_RECEIVED 11:10:27.896 IMMEDIATE_ASSIGNMENT EVENT EVENT_GPRS_MAC_MSG_SENT 11:10:27.896 Message: Packet Resource Request Channel: 0 EVENT EVENT_GPRS_PACKET_RESOURCE_REQUEST 11:10:27.896 Access Type: 0 EVENT EVENT_GSM_L1_STATE 11:10:27.909 L1_TRANSFER_MODE EVENT EVENT_GPRS_LLC_READY_TIMER_END 11:10:28.949 Length: 0013 EVENT EVENT_GPRS_TIMER_EXPIRY 11:10:30.920 GPRS Timer ID: T3168 EVENT EVENT_GPRS_TBF_RELEASE 11:10:30.920 TBF Release Type: UL_TBF_ABNORMAL EVENT EVENT_GSM_L1_STATE 11:10:30.943 L1_IDLE_MODE EVENT EVENT_GSM_L1_STATE 11:10:30.952 L1_RANDOM_ACCESS_MODE EVENT EVENT_RANDOM_ACCESS_REQUEST 11:10:30.960 1 15525 GMAC_ONE_PHASE_ACCESS EVENT EVENT_GSM_MESSAGE_RECEIVED 11:10:31.191 IMMEDIATE_ASSIGNMENT EVENT EVENT_GPRS_MAC_MSG_SENT 11:10:31.192 Message: Packet Resource Request Channel: 0 EVENT EVENT_GPRS_PACKET_RESOURCE_REQUEST 11:10:31.192 Access Type: 0 EVENT EVENT_GSM_L1_STATE 11:10:31.209 L1_TRANSFER_MODE EVENT EVENT_GPRS_TIMER_EXPIRY 11:10:34.220 GPRS Timer ID: T3168 EVENT EVENT_GPRS_TBF_RELEASE 11:10:34.220 TBF Release Type: UL_TBF_ABNORMAL EVENT EVENT_GSM_L1_STATE 11:10:34.243 L1_IDLE_MODE EVENT EVENT_GSM_L1_STATE 11:10:34.252 L1_RANDOM_ACCESS_MODE EVENT EVENT_RANDOM_ACCESS_REQUEST 11:10:34.260 1 16240 GMAC_ONE_PHASE_ACCESS EVENT EVENT_GSM_MESSAGE_RECEIVED 11:10:34.486 IMMEDIATE_ASSIGNMENT EVENT EVENT_GPRS_MAC_MSG_SENT 11:10:34.491 Message: Packet Resource Request Channel: 0 EVENT EVENT_GPRS_PACKET_RESOURCE_REQUEST 11:10:34.491 Access Type: 0 EVENT EVENT_GSM_L1_STATE 11:10:34.509 L1_TRANSFER_MODE EVENT EVENT_GPRS_TIMER_EXPIRY 11:10:37.520 GPRS Timer ID: T3168 EVENT EVENT_GPRS_TBF_RELEASE 11:10:37.520 TBF Release Type: UL_TBF_ABNORMAL EVENT EVENT_GSM_L1_STATE 11:10:37.543 L1_IDLE_MODE EVENT EVENT_GSM_L1_STATE 11:10:37.552 L1_RANDOM_ACCESS_MODE EVENT EVENT_RANDOM_ACCESS_REQUEST 11:10:37.560 1 16955 GMAC_ONE_PHASE_ACCESS EVENT EVENT_GSM_MESSAGE_RECEIVED 11:10:37.782 IMMEDIATE_ASSIGNMENT EVENT EVENT_GPRS_MAC_MSG_SENT 11:10:37.783 Message: Packet Resource Request Channel: 0 EVENT EVENT_GPRS_PACKET_RESOURCE_REQUEST 11:10:37.783 Access Type: 0 EVENT EVENT_GSM_L1_STATE 11:10:37.791 L1_TRANSFER_MODE EVENT EVENT_GPRS_TIMER_EXPIRY 11:10:40.801 GPRS Timer ID: T3168 EVENT EVENT_GPRS_TBF_RELEASE 11:10:40.802 TBF Release Type: UL_TBF_ABNORMAL EVENT EVENT_GSM_L1_STATE 11:10:40.824 L1_IDLE_MODE EVENT EVENT_GSM_L1_STATE 11:10:40.833 L1_RANDOM_ACCESS_MODE EVENT EVENT_RANDOM_ACCESS_REQUEST 11:10:40.842 1 17666 GMAC_ONE_PHASE_ACCESS EVENT EVENT_GSM_MESSAGE_RECEIVED 11:10:41.077 IMMEDIATE_ASSIGNMENT EVENT EVENT_GPRS_MAC_MSG_SENT 11:10:41.078 Message: Packet Resource Request Channel: 0 EVENT EVENT_GPRS_PACKET_RESOURCE_REQUEST 11:10:41.078 Access Type: 0 EVENT EVENT_GSM_L1_STATE 11:10:41.091 L1_TRANSFER_MODE EVENT EVENT_GPRS_TIMER_EXPIRY 11:10:44.101 GPRS Timer ID: T3168 EVENT EVENT_GPRS_TBF_RELEASE 11:10:44.102 TBF Release Type: UL_TBF_ABNORMAL EVENT EVENT_GSM_L1_STATE 11:10:44.124 L1_IDLE_MODE EVENT EVENT_GSM_L1_STATE 11:10:44.133 L1_RANDOM_ACCESS_MODE EVENT EVENT_RANDOM_ACCESS_REQUEST 11:10:44.142 1 18381 GMAC_ONE_PHASE_ACCESS EVENT EVENT_GSM_MESSAGE_RECEIVED 11:10:44.373 IMMEDIATE_ASSIGNMENT EVENT EVENT_GPRS_MAC_MSG_SENT 11:10:44.373 Message: Packet Resource Request Channel: 0 EVENT EVENT_GPRS_PACKET_RESOURCE_REQUEST 11:10:44.373 Access Type: 0 EVENT EVENT_GSM_L1_STATE 11:10:44.391 L1_TRANSFER_MODE EVENT EVENT_GPRS_TIMER_EXPIRY 11:10:47.402 GPRS Timer ID: T3168 EVENT EVENT_GPRS_TBF_RELEASE 11:10:47.402 TBF Release Type: UL_TBF_ABNORMAL EVENT EVENT_GSM_L1_STATE 11:10:47.424 L1_IDLE_MODE EVENT EVENT_GSM_L1_STATE 11:10:47.433 L1_RANDOM_ACCESS_MODE EVENT EVENT_RANDOM_ACCESS_REQUEST 11:10:47.442 1 19096 GMAC_ONE_PHASE_ACCESS EVENT EVENT_GSM_MESSAGE_RECEIVED 11:10:47.668 IMMEDIATE_ASSIGNMENT EVENT EVENT_GPRS_MAC_MSG_SENT 11:10:47.673 Message: Packet Resource Request Channel: 0 EVENT EVENT_GPRS_PACKET_RESOURCE_REQUEST 11:10:47.673 Access Type: 0 EVENT EVENT_GSM_L1_STATE 11:10:47.691 L1_TRANSFER_MODE EVENT EVENT_GPRS_TIMER_EXPIRY 11:10:50.701 GPRS Timer ID: T3168 EVENT EVENT_GPRS_TBF_RELEASE 11:10:50.702 TBF Release Type: UL_TBF_ABNORMAL EVENT EVENT_GSM_L1_STATE 11:10:50.725 L1_IDLE_MODE EVENT EVENT_GSM_L1_STATE 11:10:50.733 L1_RANDOM_ACCESS_MODE EVENT EVENT_RANDOM_ACCESS_REQUEST 11:10:50.742 1 19811 GMAC_ONE_PHASE_ACCESS EVENT EVENT_RANDOM_ACCESS_REQUEST 11:10:51.974 2 20078 GMAC_ONE_PHASE_ACCESS EVENT EVENT_GSM_MESSAGE_RECEIVED 11:10:52.140 IMMEDIATE_ASSIGNMENT EVENT EVENT_GPRS_MAC_MSG_SENT 11:10:52.141 Message: Packet Resource Request Channel: 0 EVENT EVENT_GPRS_PACKET_RESOURCE_REQUEST 11:10:52.141 Access Type: 0 EVENT EVENT_GSM_L1_STATE 11:10:52.149 L1_TRANSFER_MODE !!! Back to normal operation !!! EVENT EVENT_GPRS_MAC_MSG_RECEIVED 11:10:52.248 Message: Packet Uplink Assignment Channel: 0 EVENT EVENT_GPRS_MAC_MSG_SENT 11:10:52.248 Message: Packet Control Acknowledgement Channel: 0 EVENT EVENT_GPRS_PACKET_UPLINK_ASSIGNMENT 11:10:52.248 Time Slot Allocation: 48, Coding Scheme: 0 EVENT EVENT_GPRS_MAC_MSG_SENT 11:10:52.248 Message: Packet Uplink Dummy Control Block Channel: 0 EVENT EVENT_GPRS_MAC_MSG_RECEIVED 11:10:52.511 Message: Packet Downlink Assignment Channel: 0 EVENT EVENT_GPRS_PACKET_DOWNLINK_ASSIGNMENT 11:10:52.511 Time Slot Allocation: 112, TFI Assignment: 30

I personally convinced that the 4 UL TS utilization is just a data representation error of QXDM maybe brought to daylight by the actual problem itself, but still: the GPRS issue is very real and repeatble.

Note that the UE was in a constant location with the very same radio conditions with OpenBTS default power control settings and rxgain=25 with 3dBi omni antenna on a B200.

[dchard]

Tom Tsou introduced a new patch on the list to check if the RX chain of the SDR is overloaded or not (rxgain setting is too high, or the MS is too close to the antenna etc.).

With rxgain=25 there were no clipping detected, and I was able to reproduce the GPRS related issues.

Note: for lab testing (MS is 1-2 meter a way, with two 3-5dBi omni antennas, 90 degree aligned) both the GPRS and both the voice calls produced heavy uplink clipping with openbts default rxgain=47.

[dchard]

Some more news about GPRS Timer ID: T3168 related issue:

During the protocol analysis on OpenBTS side, I found the following:

EVENT EVENT_GSM_L1_STATE 22:02:00.088 L1_IDLE_MODE EVENT EVENT_GSM_L1_STATE 22:02:00.886 L1_RANDOM_ACCESS_MODE EVENT EVENT_RANDOM_ACCESS_REQUEST 22:02:00.923 1 422 GMAC_ONE_PHASE_ACCESS EVENT EVENT_GSM_MESSAGE_RECEIVED 22:02:01.186 IMMEDIATE_ASSIGNMENT EVENT EVENT_GPRS_MAC_MSG_SENT 22:02:01.187 Message: Packet Resource Request Channel: 0 EVENT EVENT_GPRS_PACKET_RESOURCE_REQUEST 22:02:01.187 Access Type: 0 EVENT EVENT_GSM_L1_STATE 22:02:01.199 L1_TRANSFER_MODE EVENT EVENT_GPRS_TIMER_EXPIRY 22:02:04.210 GPRS Timer ID: T3168 EVENT EVENT_GPRS_TBF_RELEASE 22:02:04.210 TBF Release Type: UL_TBF_ABNORMAL EVENT EVENT_GSM_L1_STATE 22:02:04.233 L1_IDLE_MODE EVENT EVENT_GSM_L1_STATE 22:02:04.241 L1_RANDOM_ACCESS_MODE EVENT EVENT_RANDOM_ACCESS_REQUEST 22:02:04.250 1 1143 GMAC_ONE_PHASE_ACCESS EVENT EVENT_GSM_MESSAGE_RECEIVED 22:02:04.481 IMMEDIATE_ASSIGNMENT EVENT EVENT_GPRS_MAC_MSG_SENT 22:02:04.482 Message: Packet Resource Request Channel: 0 EVENT EVENT_GPRS_PACKET_RESOURCE_REQUEST 22:02:04.482 Access Type: 0 EVENT EVENT_GSM_L1_STATE 22:02:04.499 L1_TRANSFER_MODE EVENT EVENT_GPRS_MAC_MSG_RECEIVED 22:02:04.616 Message: Packet Uplink Assignment Channel: 0

Until the second Packet resource request, the GPRS related Wireshark log was completely empty. Because there is an IMM_ASS received on the first RACH attempt, the first RACH can be considered successful, yet the first Packet resource request was sent by the MS actually never reached OpenBTS according to the Wireshark log.

During the test, no uplink clipping was detected.

[dchard]

GPRS Timer ID: T3168 related issue:

The tests were repeated with 1UL/1DL , 2UL/2DL and 2UL/3DL max TS configuration, in every case the GPRS related issue can be reproduced.

[dchard]

Protocol flow chart of the above situation:

BTS ---------------------------------- MS <---------- RACH ---------------------- ----------- IMM ASS ------------------> <---- PCKT RES. REQ. ------------- ...................................................... PCKT RES REQ, never reach BTS ....................................................... ........ GPRS T3168 Timeout ......... <---------- RACH ---------------------- ----------- IMM ASS ------------------> <---- PCKT RES. REQ. ------------- -------PCKT UPLINK ASSIGN ----->

Everything is fine from here.

Here is the protocol trace of the above situation from OpenBTS side: http://web.t-online.hu/siposjozsefdr/openbts_gprs_issue.pcapng

[dchard]

This is the OpenBTS debug log of the above test:

http://web.t-online.hu/siposjozsefdr/openbts_gprs_issue_debug_log.txt

It shows clearly that the Packet Resource Request sent by the MS actually never reaches OpenBTS, there were no uplink burst detected after the first IMM ASS reseived by the MS, until T3168 times out and the MS retries the RACH procedure.

[dchard]

With 6 GPRS timeslots enabled (max 2UL/3DL TS configuration) I conducted some tests involving two MS, both of them transmitting in the same time.

I managed to reproduce the GPRS T3168 issue with one of the MS, while the other MS was continoued the data transfer just fine.

[liorddd]

I was wondering if you mange to solve the problem concerning the gprs on openbts. I am using B210 ubunto 12.02, and got the same problem. my phone does not get attach accpet from openbts. My phone doessend attach reuest, but only after a lot of tries it recives attach accept from the openbts. It seem from the logs of openbts it does send it but i am not sure it is, only after a lot of time ( a few minutes) and a copule of tries to send attach accept, i see on my phone the attach accept. I have a phone on which i can see downlink and uplink messages.

It sounds like we have a simliar if not the same problem. Can you tell me how you solve yours?

[daniel-starke]

Check the reception level or decrease the value of the configuration parameter TRX.MinimumRxRSSI accordingly. This worked for me. Check the source code for more defails.

[daniel-starke]

I found some mobiles that ignore the L3 Attach Accept message. The reason was that OpenBTS currently sends LLC UI frames according to the "sense" of the L3 message, which is reply for Attach Accept (which is correct in L3). However, according to 04.64 chapter 8.4.1 LLC UI frames shall always be coded as command frames. A simply workaround would be to replace isCmd with true in the source code. This worked in my case.

[jarodcs]

Hi Daniel, Hi everyone

I am using the Sim800L gprs module as MS. Sometimes it connects and sends pings to an Internet IP through Openbts network, but some other times it doesn't. I am suspecting that it is the same problems exposed On this topic so I want to give a try to your suggestion about replacing 'isCmd' parameter with 'true' but i Just want to ve sure how to proceed. So, is it just a simple replacing in the source code https://github.com/RangeNetworks/openbts/blob/master/SGSNGGSN/LLC.cpp#L321 and then building the hole Openbts again? Thanks

[daniel-starke]

Hi jarodcs, yes, that is what worked out for me.

[jarodcs]

Ok Daniel, tomorrow I'll give it a try and build the hole Openbts again. I have a bounch of sim800L to stress the gprs feature. And of course I Will be back here commenting my tests. Btw, please, can you give us a little bit of inside about your troubleshooting to get with that solución... Thanks for your post.

[jarodcs]

Bingo!!!!