srsran / srsRAN_4G

Open source SDR 4G software suite from Software Radio Systems (SRS) https://docs.srsran.com/projects/4g
https://www.srsran.com
GNU Affero General Public License v3.0
3.48k stars 1.14k forks source link

eNB crahes for VoLTE call when E-RAB ID > 12 #658

Closed herlesupreeth closed 3 years ago

herlesupreeth commented 3 years ago

Issue Description

eNB crashes with the following logs, when placing 7th call from the same two UEs

Opening USRP channels=1, args: recv_frame_size=9232,send_frame_size=9232,type=b200,master_clock_rate=23.04e6
[INFO] [UHD RF] RF UHD Generic instance constructed
[INFO] [B200] Detected Device: B210
[INFO] [B200] Operating over USB 3.
[INFO] [B200] Initialize CODEC control...
[INFO] [B200] Initialize Radio control...
[INFO] [B200] Performing register loopback test... 
[INFO] [B200] Register loopback test passed
[INFO] [B200] Performing register loopback test... 
[INFO] [B200] Register loopback test passed
[INFO] [B200] Asking for clock rate 23.040000 MHz... 
[INFO] [B200] Actually got clock rate 23.040000 MHz.
Setting frequency: DL=2660.0 Mhz, UL=2540.0 MHz for cc_idx=0 nof_prb=25

==== eNodeB started ===
Type <t> to view trace
RACH:  tti=4211, cc=0, preamble=36, offset=0, temp_crnti=0x46
User 0x46 connected
User 0x46 connected
RACH:  tti=8431, cc=0, preamble=17, offset=0, temp_crnti=0x47
User 0x47 connected
User 0x47 connected
User 0x46 connected
User 0x47 connected
User 0x46 connected
User 0x47 connected
User 0x46 connected
User 0x47 connected
User 0x46 connected
User 0x47 connected
User 0x46 connected
User 0x47 connected
User 0x46 connected
User 0x47 connected
User 0x47 connected
User 0x46 connected
User 0x46 connected
User 0x47 connected
User 0x47 connected
User 0x46 connected
User 0x46 connected
User 0x47 connected
User 0x46 connected
User 0x47 connected
User 0x46 connected
User 0x47 connected
terminate called after throwing an instance of 'std::bad_alloc'
  what():  std::bad_alloc
srsRAN crashed... backtrace saved in './srsRAN.backtrace.crash'...
---  exiting  ---
srsRAN crashed... backtrace saved in './srsRAN.backtrace.crash'...
---  exiting  ---
terminate called recursively
srsRAN crashed... backtrace saved in './srsRAN.backtrace.crash'...
---  exiting  ---

Setup Details

Running srsRAN enB (master) + open5gs EPC (tag v2.2.7) + kamailio IMS all in docker setup - https://github.com/herlesupreeth/docker_open5gs

SDR - USRP B210 UEs with sysmocom USIM/ISIM - Xiaomi phone and iPhone X

Expected Behavior

Should not crash

Actual Behaviour

eNB crashes the moment i attempt 7th call and works good for all the previous 6 calls

Steps to reproduce the problem

Additional Information

In order to allow E-RAB ID > 12 i.e. LCID > 10, I have done the following modification to srsRAN eNB. No other modification has been done

diff --git a/lib/include/srsran/common/common.h b/lib/include/srsran/common/common.h
index c0f5f5598..c341b24c3 100644
--- a/lib/include/srsran/common/common.h
+++ b/lib/include/srsran/common/common.h
@@ -40,8 +40,8 @@
 #define SRSRAN_UE_CATEGORY 4

 #define SRSRAN_N_SRB 3
-#define SRSRAN_N_DRB 11
-#define SRSRAN_N_RADIO_BEARERS 14
+#define SRSRAN_N_DRB 8
+#define SRSRAN_N_RADIO_BEARERS 11

 #define SRSRAN_N_MCH_LCIDS 32

I have attached the logs (INFO level), backtrace (taken with -DCMAKE_BUILD_TYPE=RelWithDebInfo), pcaps below. Please let me know if you need further details. log_bt_pcap.zip

andrepuschmann commented 3 years ago

Good catch. Thanks, Supreeth. We'll look into this.

davidrupprecht commented 3 years ago

Dear @herlesupreeth, thanks for the catch. Can you install libdw-dev recompile it, trigger the bug again and send me the stack trace. Thanks a lot.

herlesupreeth commented 3 years ago

@davidrupprecht sure will do that. Thank you

herlesupreeth commented 3 years ago

Please find the log, pcaps and backtrace attached. Let me know if you need anything else log_bt_pcap2.zip

Its the one with this timestamp

--- command='/usr/local/bin/srsenb' version=21.04.0 signal=6 date='03/05/2021 10:31:51' ---

davidrupprecht commented 3 years ago

Unfortunately the stacktrace did not use the latest stacktrace printer. Can you run cmake .. -DCMAKE_BUILD_TYPE=RelWithDebInfo and see if is building with Building with backward-cpp support or the HAVE_BACKWARD flag is enabled. Thanks.

herlesupreeth commented 3 years ago

My bad, i installed that library after compilation. Please find the trace after re-compiling. Following are the logs + backtrace. I also have the coredump but its around 120 MB, let me know if you need it.

srsRAN.backtrace.zip

Creating srsenb ... done
Attaching to srsenb
srsenb    | ---  Software Radio Systems LTE eNodeB  ---
srsenb    | 
srsenb    | Reading configuration file /etc/srsran/enb.conf...
srsenb    | 
srsenb    | Built in RelWithDebInfo mode using commit 3a0e7bb6a on branch crash_fix.
srsenb    | 
srsenb    | Opening 1 channels in RF device=default with args=clock=external,recv_frame_size=9232,send_frame_size=9232
srsenb    | [INFO] [UHD] linux; GNU C++ version 7.5.0; Boost_106501; UHD_3.15.0.0-release
srsenb    | [INFO] [LOGGING] Fastpath logging disabled at runtime.
srsenb    | Opening USRP channels=1, args: recv_frame_size=9232,send_frame_size=9232,type=b200,master_clock_rate=23.04e6
srsenb    | [INFO] [UHD RF] RF UHD Generic instance constructed
srsenb    | [INFO] [B200] Detected Device: B210
srsenb    | [INFO] [B200] Operating over USB 3.
srsenb    | [INFO] [B200] Initialize CODEC control...
srsenb    | [INFO] [B200] Initialize Radio control...
srsenb    | [INFO] [B200] Performing register loopback test... 
srsenb    | [INFO] [B200] Register loopback test passed
srsenb    | [INFO] [B200] Performing register loopback test... 
srsenb    | [INFO] [B200] Register loopback test passed
srsenb    | [INFO] [B200] Asking for clock rate 23.040000 MHz... 
srsenb    | [INFO] [B200] Actually got clock rate 23.040000 MHz.
srsenb    | Setting frequency: DL=2660.0 Mhz, UL=2540.0 MHz for cc_idx=0 nof_prb=25
srsenb    | 
srsenb    | ==== eNodeB started ===
srsenb    | Type <t> to view trace
srsenb    | RACH:  tti=4421, cc=0, preamble=40, offset=0, temp_crnti=0x46
srsenb    | User 0x46 connected
srsenb    | User 0x46 connected
srsenb    | RACH:  tti=9801, cc=0, preamble=30, offset=0, temp_crnti=0x47
srsenb    | User 0x47 connected
srsenb    | User 0x47 connected
srsenb    | User 0x46 connected
srsenb    | User 0x47 connected
srsenb    | User 0x46 connected
srsenb    | User 0x47 connected
srsenb    | RACH:  tti=5891, cc=0, preamble=42, offset=0, temp_crnti=0x48
srsenb    | RACH:  tti=5901, cc=0, preamble=37, offset=0, temp_crnti=0x49
srsenb    | Disconnecting rnti=0x47.
srsenb    | Disconnecting rnti=0x46.
srsenb    | User 0x48 connected
srsenb    | User 0x49 connected
srsenb    | User 0x49 connected
srsenb    | User 0x48 connected
srsenb    | User 0x48 connected
srsenb    | User 0x49 connected
srsenb    | User 0x48 connected
srsenb    | User 0x49 connected
srsenb    | User 0x48 connected
srsenb    | User 0x49 connected
srsenb    | User 0x49 connected
srsenb    | User 0x48 connected
srsenb    | User 0x48 connected
srsenb    | User 0x49 connected
srsenb    | User 0x48 connected
srsenb    | User 0x49 connected
srsenb    | User 0x48 connected
srsenb    | User 0x49 connected
srsenb    | User 0x48 connected
srsenb    | User 0x49 connected
srsenb    | User 0x48 connected
srsenb    | User 0x49 connected
srsenb    | terminate called after throwing an instance of 'std::bad_alloc'
srsenb    |   what():  std::bad_alloc
srsenb    | Stack trace (most recent call last) in thread 56:
srsenb    | #14   Object "", at 0xffffffffffffffff, in 
srsenb    | Stack trace (most recent call last) in thread 51:
srsenb    | #16   Object "", at 0xffffffffffffffff, in 
srsenb    | #13   Source "../sysdeps/unix/sysv/linux/x86_64/clone.S", line 95, in __clone [0x7fc2d04ce71e]
srsenb    | #15   Source "../sysdeps/unix/sysv/linux/x86_64/clone.S", line 95, in __clone [0x7fc2d04ce71e]
srsenb    | #12   Source "/build/glibc-S9d2JN/glibc-2.27/nptl/pthread_create.c", line 463, in start_thread [0x7fc2d26056da]#14   Source "/build/glibc-S9d2JN/glibc-2.27/nptl/pthread_create.c", line 463, in start_thread [0x7fc2d26056da]
srsenb    | 
srsenb    | #13   Source "/srsLTE/lib/include/srsran/common/threads.h", line 111, in thread_function_entry [0x5640b33e5ebd]
srsenb    |         108:   static void* thread_function_entry(void* _this)
srsenb    |         109:   {
srsenb    |         110:     pthread_setname_np(pthread_self(), ((thread*)_this)->name.c_str());
srsenb    |       > 111:     ((thread*)_this)->run_thread();
srsenb    |         112:     return NULL;
srsenb    |         113:   }
srsenb    | #11   Source "/srsLTE/lib/include/srsran/common/threads.h", line 111, in thread_function_entry [0x5640b33e5ebd]
srsenb    |         108:   static void* thread_function_entry(void* _this)
srsenb    |         109:   {
srsenb    |         110:     pthread_setname_np(pthread_self(), ((thread*)_this)->name.c_str());
srsenb    |       > 111:     ((thread*)_this)->run_thread();
srsenb    |         112:     return NULL;
srsenb    |         113:   }
srsenb    | #12   Source "/srsLTE/lib/src/common/thread_pool.cc", line 57, in run_thread [0x5640b35a6c28]
srsenb    |          54:   while (my_parent->status[my_id] != STOP) {
srsenb    |          55:     wait_to_start();
srsenb    |          56:     if (my_parent->status[my_id] != STOP) {
srsenb    |       >  57:       work_imp();
srsenb    |          58:       finished();
srsenb    |          59:     }
srsenb    |          60:   }
srsenb    | #11   Source "/srsLTE/srsenb/src/phy/lte/sf_worker.cc", line 207, in work_imp [0x5640b34191e6]
srsenb    |         205:   // Get DL scheduling for the TX TTI from MAC
srsenb    |         206:   if (sf_type == SRSRAN_SF_NORM) {
srsenb    |       > 207:     if (stack->get_dl_sched(tti_tx_dl, dl_grants) < 0) {
srsenb    |         208:       Error("Getting DL scheduling from MAC");
srsenb    |         209:       phy->worker_end(this, tx_buffer, tx_time);
srsenb    |         210:       return;
srsenb    | #10   Source "/srsLTE/srsenb/src/stack/mac/mac.cc", line 610, in get_dl_sched [0x5640b3465482]
srsenb    |         607:   for (uint32_t enb_cc_idx = 0; enb_cc_idx < cell_config.size(); enb_cc_idx++) {
srsenb    |         608:     // Run scheduler with current info
srsenb    |         609:     sched_interface::dl_sched_res_t sched_result = {};
srsenb    |       > 610:     if (scheduler.dl_sched(tti_tx_dl, enb_cc_idx, sched_result) < 0) {
srsenb    |         611:       logger.error("Running scheduler");
srsenb    |         612:       return SRSRAN_ERROR;
srsenb    |         613:     }
srsenb    | #10 | Source "/srsLTE/srsenb/src/stack/enb_stack_lte.cc", line 238, in run_next_task
srsenb    |     |   236: {
srsenb    |     |   237:   while (started) {
srsenb    |     | > 238:     task_sched.run_next_task();
srsenb    |     |   239:   }
srsenb    |     |   240: }
srsenb    |     | Source "/srsLTE/lib/include/srsran/common/task_scheduler.h", line 80, in operator()
srsenb    |     |    78:     srsran::move_task_t task{};
srsenb    |     |    79:     if (external_tasks.wait_pop(&task) >= 0) {
srsenb    |     | >  80:       task();
srsenb    |     |    81:       run_all_internal_tasks();
srsenb    |     |    82:       return true;
srsenb    |       Source "/srsLTE/lib/include/srsran/adt/pool/../move_callback.h", line 178, in run_thread [0x5640b34257f0]
srsenb    |         175:     return *this;
srsenb    |         176:   }
srsenb    |         177: 
srsenb    |       > 178:   R operator()(Args... args) const noexcept { return oper_ptr->call(&buffer, std::forward<Args>(args)...); }
srsenb    |         179: 
srsenb    |         180:   bool is_empty() const { return oper_ptr == &empty_table; }
srsenb    |         181:   bool is_in_small_buffer() const { return oper_ptr->is_in_small_buffer(); }
srsenb    | #9  | Source "/srsLTE/lib/include/srsran/adt/pool/../move_callback.h", line 101, in operator()<>
srsenb    |     |    99: public:
srsenb    |     |   100:   constexpr heap_table_t() = default;
srsenb    |     | > 101:   R    call(void* src, Args... args) const final { return (**static_cast<FunT**>(src))(std::forward<Args>(args)...); }
srsenb    |     |   102:   void move(void* src, void* dest) const final
srsenb    |     |   103:   {
srsenb    |     | Source "/usr/include/c++/7/functional", line 551, in __call<void, 0>
srsenb    | #9    Source "/srsLTE/srsenb/src/stack/mac/sched.cc", line 310, in dl_sched [0x5640b34773f0]
srsenb    |         307:   }
srsenb    |         308: 
srsenb    |         309:   tti_point tti_rx = tti_point{tti_tx_dl} - TX_ENB_DELAY;
srsenb    |       > 310:   new_tti(tti_rx);
srsenb    |         311: 
srsenb    |         312:   // copy result
srsenb    |         313:   sched_result = sched_results.get_sf(tti_rx)->get_cc(enb_cc_idx)->dl_sched_result;
srsenb    |     |   549:      return this->__call<_Result>(
srsenb    |     |   550:          std::forward_as_tuple(std::forward<_Args>(__args)...),
srsenb    |     | > 551:          _Bound_indexes());
srsenb    |     |   552:    }
srsenb    |     | Source "/usr/include/c++/7/functional", line 467, in __invoke<srsran::sctp_recvmsg_pdu_task::operator()(int)::<lambda(srsran::unique_byte_buffer_t&)>&, std::unique_ptr<srsran::byte_buffer_t, std::default_delete<srsran::byte_buffer_t> >&>
srsenb    |     |   465:    __call(tuple<_Args...>&& __args, _Index_tuple<_Indexes...>)
srsenb    |     |   466:    {
srsenb    |     | > 467:      return std::__invoke(_M_f,
srsenb    |     |   468:          _Mu<_Bound_args>()(std::get<_Indexes>(_M_bound_args), __args)...
srsenb    |     |   469:          );
srsenb    |     | Source "/usr/include/c++/7/bits/invoke.h", line 95, in __invoke_impl<void, srsran::sctp_recvmsg_pdu_task::operator()(int)::<lambda(srsran::unique_byte_buffer_t&)>&, std::unique_ptr<srsran::byte_buffer_t, std::default_delete<srsran::byte_buffer_t> >&>
srsenb    |     |    93:       using __type = typename __result::type;
srsenb    |     |    94:       using __tag = typename __result::__invoke_type;
srsenb    |     | >  95:       return std::__invoke_impl<__type>(__tag{}, std::forward<_Callable>(__fn),
srsenb    |     |    96:                    std::forward<_Args>(__args)...);
srsenb    |     |    97:     }
srsenb    |     | Source "/usr/include/c++/7/bits/invoke.h", line 60, in operator()
srsenb    |     |    58:     constexpr _Res
srsenb    |     |    59:     __invoke_impl(__invoke_other, _Fn&& __f, _Args&&... __args)
srsenb    |     | >  60:     { return std::forward<_Fn>(__f)(std::forward<_Args>(__args)...); }
srsenb    |     |    61: 
srsenb    |     |    62:   template<typename _Res, typename _MemFun, typename _Tp, typename... _Args>
srsenb    |     | Source "/srsLTE/lib/src/common/network_utils.cc", line 581, in operator()
srsenb    |     |   579:     // SCTP notifications handled in callback.
srsenb    |     |   580:     queue.push(std::bind(
srsenb    |     | > 581:         [this, from, sri, flags](srsran::unique_byte_buffer_t& sdu) { func(std::move(sdu), from, sri, flags); },
srsenb    |     |   582:         std::move(pdu)));
srsenb    |     |   583:     return ret;
srsenb    |       Source "/srsLTE/lib/include/srsran/adt/pool/../move_callback.h", line 178, in call [0x5640b35a06a9]
srsenb    |         175:     return *this;
srsenb    |         176:   }
srsenb    |         177: 
srsenb    |       > 178:   R operator()(Args... args) const noexcept { return oper_ptr->call(&buffer, std::forward<Args>(args)...); }
srsenb    |         179: 
srsenb    |         180:   bool is_empty() const { return oper_ptr == &empty_table; }
srsenb    |         181:   bool is_in_small_buffer() const { return oper_ptr->is_in_small_buffer(); }
srsenb    | #8    Source "/srsLTE/srsenb/src/stack/mac/sched.cc", line 350, in new_tti [0x5640b34761e3]
srsenb    |         347:   for (size_t cc_idx = 0; cc_idx < carrier_schedulers.size(); ++cc_idx) {
srsenb    |         348:     if (not is_generated(tti_rx, cc_idx)) {
srsenb    |         349:       // Generate carrier scheduling result
srsenb    |       > 350:       carrier_schedulers[cc_idx]->generate_tti_result(tti_rx);
srsenb    |         351:     }
srsenb    |         352:   }
srsenb    |         353: }
srsenb    | #7    Source "/srsLTE/srsenb/src/stack/mac/sched_carrier.cc", line 422, in generate_tti_result [0x5640b3485478]
srsenb    |         419:   }
srsenb    |         420: 
srsenb    |         421:   /* Schedule DL user data */
srsenb    |       > 422:   alloc_dl_users(tti_sched);
srsenb    |         423: 
srsenb    |         424:   if ((tti_rx.to_uint() % 2) == 1) {
srsenb    |         425:     alloc_ul_users(tti_sched);
srsenb    | #8  | Source "/srsLTE/lib/include/srsran/adt/pool/../move_callback.h", line 85, in operator()
srsenb    |     |    83: public:
srsenb    |     |    84:   constexpr smallbuffer_table_t() = default;
srsenb    |     | >  85:   R    call(void* src, Args... args) const final { return (*static_cast<FunT*>(src))(std::forward<Args>(args)...); }
srsenb    |     |    86:   void move(void* src, void* dest) const final
srsenb    |     |    87:   {
srsenb    |     | Source "/srsLTE/srsenb/src/stack/upper/s1ap.cc", line 501, in ~unique_ptr
srsenb    |     |   499:       [this](srsran::unique_byte_buffer_t pdu, const sockaddr_in& from, const sctp_sndrcvinfo& sri, int flags) {
srsenb    |     |   500:         // Defer the handling of MME packet to eNB stack main thread
srsenb    |     | > 501:         handle_mme_rx_msg(std::move(pdu), from, sri, flags);
srsenb    |     |   502:       };
srsenb    |     |   503:   rx_socket_handler->add_socket_handler(mme_socket.fd(),
srsenb    |     | Source "/usr/include/c++/7/bits/unique_ptr.h", line 263, in operator()
srsenb    |     |   261:    auto& __ptr = _M_t._M_ptr();
srsenb    |     |   262:    if (__ptr != nullptr)
srsenb    |     | > 263:      get_deleter()(__ptr);
srsenb    |     |   264:    __ptr = pointer();
srsenb    |     |   265:       }
srsenb    |       Source "/usr/include/c++/7/bits/unique_ptr.h", line 78, in call [0x5640b34585ce]
srsenb    |          75:              "can't delete pointer to incomplete type");
srsenb    |          76:    static_assert(sizeof(_Tp)>0,
srsenb    |          77:              "can't delete pointer to incomplete type");
srsenb    |       >  78:    delete __ptr;
srsenb    |          79:       }
srsenb    |          80:     };
srsenb    | #7    Object "/lib/x86_64-linux-gnu/libgcc_s.so.1", at 0x7fc2d07aedf4, in _Unwind_Resume
srsenb    | #6    Object "/lib/x86_64-linux-gnu/libgcc_s.so.1", at 0x7fc2d07ae572, in 
srsenb    | #5    Object "/usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.25", at 0x7fc2d0de64b7, in __gxx_personality_v0
srsenb    | #4    Object "/usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.25", at 0x7fc2d0de5b48, in 
srsenb    | #3    Object "/usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.25", at 0x7fc2d0de6ae5, in 
srsenb    | #2    Object "/usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.25", at 0x7fc2d0de0956, in 
srsenb    | #1    Source "/build/glibc-S9d2JN/glibc-2.27/stdlib/abort.c", line 79, in abort [0x7fc2d03ed920]
srsenb    | #0    Source "../sysdeps/unix/sysv/linux/raise.c", line 51, in raise [0x7fc2d03ebfb7]
srsenb    | Aborted (Signal sent by tkill() 22 0)
srsenb    | #6    Source "/srsLTE/srsenb/src/stack/mac/sched_carrier.cc", line 457, in __stack_chk_fail [0x5640b3481bfb]
srsenb    |         454:   }
srsenb    |         455: 
srsenb    |         456:   // call DL scheduler metric to fill RB grid
srsenb    |       > 457:   sched_algo->sched_dl_users(*ue_db, tti_result);
srsenb    |         458: }
srsenb    |         459: 
srsenb    |         460: int sched::carrier_sched::alloc_ul_users(sf_sched* tti_sched)
srsenb    | Aborted (core dumped)
srsenb exited with code 134
frankist commented 3 years ago

Hey @herlesupreeth. Can you try to set MAX_LC = 13 in lib/include/srsran/interfaces/sched_interface.h and see if the issue vanishes? If so, we will provide a fix.

herlesupreeth commented 3 years ago

Hey @frankist , unfortunately, that didnt solve the entire issue. Atleast now it doesn't crash but on the 7th call, UE doesnt receive the call at all, its like as though there is no GTP tunnel.

Please find the logs and pcap attached

In the logs i found this error


15:52:53.050892 [ASN1   ] [E] [    0] [/srsLTE/lib/src/asn1/rrc/rr_ded.cc][4140] Encoding failure.
15:52:53.050892 [ASN1   ] [E] [    0] [/srsLTE/lib/include/srsran/asn1/asn1_utils.h][1043] Encoding failure.
15:52:53.050893 [ASN1   ] [E] [    0] [/srsLTE/lib/src/asn1/rrc/rr_ded.cc][8477] Encoding failure.
15:52:53.050893 [ASN1   ] [E] [    0] [/srsLTE/lib/src/asn1/rrc/dl_dcch_msg.cc][12341] Encoding failure.
15:52:53.050893 [ASN1   ] [E] [    0] [/srsLTE/lib/src/asn1/rrc/dl_dcch_msg.cc][13991] Encoding failure.
15:52:53.050893 [ASN1   ] [E] [    0] [/srsLTE/lib/src/asn1/rrc/dl_dcch_msg.cc][13894] Encoding failure.
15:52:53.050894 [ASN1   ] [E] [    0] [/srsLTE/lib/src/asn1/rrc/dl_dcch_msg.cc][13841] Encoding failure.
15:52:53.050894 [ASN1   ] [E] [    0] [/srsLTE/lib/src/asn1/rrc/dl_dcch_msg.cc][14981] Encoding failure.
15:52:53.050894 [ASN1   ] [E] [    0] [/srsLTE/lib/src/asn1/rrc/dl_dcch_msg.cc][14575] Encoding failure.
15:52:53.050894 [ASN1   ] [E] [    0] [/srsLTE/lib/src/asn1/rrc/dl_dcch_msg.cc][15080] Encoding failure.
15:52:53.050895 [RRC    ] [E] Failed to encode DL-DCCH-Msg
15:52:53.050913 [S1AP   ] [I] Tx S1AP SDU, E_RABSetupResponse

debug_1.zip

herlesupreeth commented 3 years ago

I have submitted a PR to fix this issue, it would be great if you could review it and let me you know your feedback.

I have tested its working as well. Please refer to the attached pcap for verify its working erab_fix.zip

Looking forward to your feedback

andrepuschmann commented 3 years ago

Thanks for the PR Supreeth. Actually, we have already been working on a fix for it internally. Besides using two Android phones and doing a VoLTE call between do you know of any other way to trigger the ERAB creation from the EPC side to trigger the bug?

herlesupreeth commented 3 years ago

I know a way to trigger couple of eRAB creation from open5gs WebUI but not sure whether its able to trigger e-RAB until the e-RAB Id > 12.

Goto to open5gs WebUI where you add SIM details

  1. Click on "PCC Rules" under internet APN, there set MBR Downlink/Uplink, GBR Downlink/Uplink to any desired value (for VoLTE call its enough to have value of 64 there)
  2. Right under PCC rules there is a small "+" button upon pressing it you get to provide flow description (as shown in screenshot below) image
  3. Here you can provide flow description as following
Flow Direction* - Downlink
Description - permit out 17 from <ANY_IP> <ANY_PORT> to any

Add another flow rule

Flow Direction* - Uplink
Description - permit out 17 from <ANY_IP> <ANY_PORT> to any

replace and with the any random IP and port you want

This will trigger E-RAB Setup for one bearer

  1. For triggering further bearer creations, i would suggest to add further PCC rules with varying QCI and ARP and adding flow description as above for each PCC rule (dont forget to add DRB configuration at eNB for all the QCIs created in WebUI)
herlesupreeth commented 3 years ago

Just another update

For triggering further bearer creations, i would suggest to add further PCC rules with varying QCI and ARP and adding flow description as above for each PCC rule (dont forget to add DRB configuration at eNB for all the QCIs created in WebUI)

You can add PCC rules with same QCI and ARP but different flow-descriptions to trigger another e-RAB setup

andrepuschmann commented 3 years ago

Hey @herlesupreeth, I was trying to reproduce the issue with our third-party EPC solution (Amarisoft) but the issue isn't triggered because Amarisoft reuses E-RABs and doesn't increase the ID beyond the radio bearer it creates. Note that we reach the limit for DRBs or LCIDs at MAC layer earlier than we reach E-RAB ID > 12. So this is perfectly fine.

I've therefore started on using open5gs in our CI. The suggested way of creating multiple bearers using the web GUI isn't possible in our current arch. Is there a way to put the rules for dedicated bearers inside a config file?

Thanks Andre

kbarlee commented 3 years ago

Hey Andre

I guess you could use https://github.com/open5gs/open5gs/blob/main/misc/db/open5gs-dbctl as an example, and modify to set the subscriber pcc rules via a script. Something along these lines?

#!/bin/bash

IMSI=001010000000001
MSISDN=0000000001
KI=465B5CE8B199B49FAA5F0A2EE238A6BC
OPC=E8ED289DEBA952E4283B54E88E6183CA

mongo --eval "db.subscribers.update( { \"imsi\" : \"$IMSI\" },
    { \$setOnInsert:
        {
            \"imsi\" : \"$IMSI\",
            \"subscribed_rau_tau_timer\" : NumberInt(12),
            \"network_access_mode\" : NumberInt(2),
            \"subscriber_status\" : NumberInt(0),
            \"access_restriction_data\" : NumberInt(32),
            \"slice\" :
            [{
                \"sst\" : NumberInt(1),
                \"default_indicator\" : true,
                \"_id\" : new ObjectId(),
                \"session\" :
                [{
                    \"name\" : \"internet\",
                    \"type\" : NumberInt(3),
                    \"_id\" : new ObjectId(),
                    \"pcc_rule\" : [{
                        \"qos\" : { 
                            \"index\" : NumberInt(1),
                            \"gbr\" : {
                                \"uplink\" : { \"value\": NumberInt(1), \"unit\" : NumberInt(3) },
                                \"downlink\" : { \"value\": NumberInt(1), \"unit\" : NumberInt(3) }
                            },
                            \"mbr\" : {
                                \"uplink\" : { \"value\": NumberInt(1), \"unit\" : NumberInt(3) },
                                \"downlink\" : { \"value\": NumberInt(1), \"unit\" : NumberInt(3) }
                            },
                            \"arp\" : {
                                \"priority_level\" : NumberInt(2),
                                \"pre_emption_capability\" : NumberInt(2),
                                \"pre_emption_vulnerability\" : NumberInt(2)
                            }
                        },
                        \"flow\" : [
                            {
                                \"direction\" : NumberInt(1),
                                \"description\" : \"permit out udp from any 1-65535 to 45.45.45.45\",
                            },
                            {
                                \"direction\" : NumberInt(2),
                                \"description\" : \"permit out udp from any 1-65535 to 45.45.45.45\",
                            },
                        ]
                    }],
                    \"ambr\" :
                    {
                        \"uplink\" : { \"value\": NumberInt(1), \"unit\" : NumberInt(3) },
                        \"downlink\" : { \"value\": NumberInt(1), \"unit\" : NumberInt(3) },
                    },
                    \"qos\" :
                    {
                        \"index\" : NumberInt(9),
                        \"arp\" :
                        {
                            \"priority_level\" : NumberInt(8),
                            \"pre_emption_capability\" : NumberInt(1),
                            \"pre_emption_vulnerability\" : NumberInt(1),
                        },
                    },
                }],
            }],
            \"ambr\" :
            {
                \"uplink\" : { \"value\": NumberInt(1), \"unit\" : NumberInt(3) },
                \"downlink\" : { \"value\": NumberInt(1), \"unit\" : NumberInt(3) },
            },
            \"security\" :
            {
                \"k\" : \"$KI\",
                \"amf\" : \"8000\",
                \"op\" : null,
                \"opc\" : \"$OPC\",
                \"msisdn\" : [ \"$MSISDN\" ],
                \"schema_version\" : NumberInt(1),
            },
            \"__v\" : 0
        },
    },
    upsert=true);" open5gs
exit 0

Cheers Kenny

andrepuschmann commented 3 years ago

Thanks @kbarlee for the advice. I am very new to open5gs and its currently giving me some serious headaches. I'll give your proposal a try as soon as we have a reliable CI setup with it running.

Meanwhile, we've collected a few commits that would be nice to test before submission. @herlesupreeth could you perhaps try https://github.com/srsran/srsRAN/tree/release_21_04_final with your setup that led to the eNB crash? It includes a couple of more fixes as well. Unfortunately, I couldn't replicate the issue here locally so it would be nice to make sure it's fixed for you.

Thanks Andre

herlesupreeth commented 3 years ago

@andrepuschmann I tried with the branch mentioned, but i have an issue. While I placed the first VoLTE call the call gets connected, then i disconnected the call and tried placing another call but this did not work at all (tried this scenario 4 times, same result). In the pcap you can see that for the 2nd call there is no "Activate deidicated EPS Bearer Context Accept"

Please find the pcap and enb.log attached log_pcap.zip

frankist commented 3 years ago

Hey @herlesupreeth . Could you please increase the log all_hex_limit to 4096 and send new logs? This way, I can see the entirity of the packets being exchanged between the enb and UE.

frankist commented 3 years ago

@herlesupreeth could you also rebase your fix on https://github.com/srsran/srsRAN/tree/release_21_04_final. This way it will be easier to include your commit changes.

herlesupreeth commented 3 years ago

@frankist sure will do

herlesupreeth commented 3 years ago

@frankist Please find the logs with increased hex limit attached (tested with release_21_04_final branch)

enb_log_4096.zip

andrepuschmann commented 3 years ago

@herlesupreeth We've consolidated a few patches and would like to ask you to test your scenario again. It is included in this "new" branch https://github.com/srsran/srsRAN/tree/release_21_04_erab_fixes Thanks again for your help. Much appreciated!

herlesupreeth commented 3 years ago

@andrepuschmann Tried the suggested branch. Facing the same issue where I place the first VoLTE call the call gets connected, then i disconnected the call and tried placing another call but this did not work at all. In the pcap you can see that for the 2nd call there is no "Activate dedicated EPS Bearer Context Accept" again log_pcap.zip

Btw, I had look into this commit https://github.com/srsran/srsRAN/commit/d81788e077a97bf1aedbe48eb8989766e50ec216, i think we cannot have fixed DRB and LCID mappings since the maximum number of DRBs in LTE can go upto 11 where as the LCIDs that can be used for DRBs are 3..10. Please correct me if I am wrong

andrepuschmann commented 3 years ago

@herlesupreeth Actually the NAS message for the dedicated bearer activation wasn't sent. We'll provide another patch shortly. Thanks again

andrepuschmann commented 3 years ago

Here https://github.com/srsran/srsRAN/tree/fix_erabid_to_drb_conversions is the new branch (just differs in one commit) for you to try. Let me know how it goes. If it doesn't work, please send also the eNB MAC PCAP along. Thanks

herlesupreeth commented 3 years ago

@andrepuschmann Thank you. I tested the branch and it works flawlessly

andrepuschmann commented 3 years ago

Excellent. Thanks for your help and support again @herlesupreeth.

Closing the issue now as the fixes will be included in master soon.