Project

General

Profile

Bug #2505

ofono on osmo-gsm-tester RnD crashes

Added by neels 12 days ago. Updated 7 days ago.

Status:
Resolved
Priority:
High
Assignee:
Target version:
-
Start date:
09/07/2017
Due date:
% Done:

0%

Spec Reference:

Description

On RnD, running the https://jenkins.osmocom.org/jenkins/job/osmo-gsm-tester_manual-run-all
apparently consistently crashes ofono when the sysmocell5000 test starts.

Logs follow.


Subtasks

Bug #2511: ofono: check all services for simple use before register race conditionNewlynxis

History

#1 Updated by neels 12 days ago

syslog says:

Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: drivers/qmimodem/sim.c:get_file_attributes_cb()
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: drivers/qmimodem/sim.c:qmi_read_record() file id 0x6f40 path len 0
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: QMI: > 01 22 00 00 0b 01 00 26 01 21 00 16 00 01 02 00  .".....&.!......
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: QMI:   00 00 02 07 00 40 6f 04 00 3f ff 7f 03 04 00 01  .....@o..?......
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: QMI:   00 22 00                                         .".
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: QMI:     UIM_req msg=33 len=22 [client=1,type=0,tid=294,len=34]
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: QMI:        {type=1,len=2} {type=2,len=7} {type=3,len=4}
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: drivers/qmimodem/qmibridge.c:ask_qmi() _REQ: QMI QMUX:#012QMI   length  = 34#012QMI   flags   = 0x00#012QMI   service = "uim"#012QMI   client  = 1#012QMI QMI:#012
QMI   flags       = "none"#012QMI   transaction = 294#012QMI   tlv_length  = 22#012QMI   message     = "Read Record" (0x0021)#012QMI TLV:#012QMI   type       = "Session Information" (0x01)#012QMI   length     = 2
#012QMI   value      = 00:00#012QMI   translated = [ session_type = 'primary-gw-provisioning' application_identifier = '' ]#012QMI TLV:#012QMI   type       = "File" (0x02)#012QMI   length     = 7#012QMI   value  
    = 40:6F:04:00:3F:FF:7F#012QMI   translated = [ file_id = '28480' file_path = '{ [0] = '0 ' [1] = '63 ' [2] = '255 ' [3] = '127 '}' ]#012QMI TLV:#012QMI   type       = "Record" (0x03)#012QMI   length     = 4#0
12QMI   value      = 01:00:22:00#012QMI   translated = [ record_number = '1' record_length = '34' ]
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: QMI: < 01 21 00 80 03 01 04 00 00 24 00 15 00 22 05 00  .!.......$..."..
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: QMI:   00 01 00 01 00 11 01 00 00 01 06 00 02 00 00 00  ................
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: QMI:   01 00                                            ..
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: drivers/qmimodem/qmibridge.c:ask_qmi() READ: QMI QMUX:#012QMI   length  = 33#012QMI   flags   = 0x80#012QMI   service = "nas"#012QMI   client  = 1#012QMI QMI:#012
QMI   flags       = "indication"#012QMI   transaction = 0#012QMI   tlv_length  = 21#012QMI   message     = "Serving System" (0x0024)#012QMI TLV:#012QMI   type       = "Detailed Service Status" (0x22)#012QMI   len
gth     = 5#012QMI   value      = 00:01:00:01:00#012QMI   translated = [ status = 'none' capability = 'cs' hdr_status = 'none' hdr_hybrid = 'yes' forbidden = 'no' ]#012QMI TLV:#012QMI   type       = "Data Service
 Capability" (0x11)#012QMI   length     = 1#012QMI   value      = 00#012QMI   translated = {}#012QMI TLV:#012QMI   type       = "Serving System" (0x01)#012QMI   length     = 6#012QMI   value      = 02:00:00:00:01
:00#012QMI   translated = [ registration_state = 'not-registered-searching' cs_attach_state = 'unknown' ps_attach_state = 'unknown' selected_network = 'unknown' radio_interfaces = '{ [0] = 'none '}' ]
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: QMI:     NAS_ind msg=36 len=21 [client=1,type=4,tid=0,len=33]
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: QMI:        {type=34,len=5} {type=17,len=1} {type=1,len=6}
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: QMI: < 01 21 00 80 03 02 04 00 00 24 00 15 00 22 05 00  .!.......$..."..
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: QMI:   00 01 00 01 00 11 01 00 00 01 06 00 02 00 00 00  ................
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: QMI:   01 00                                            ..
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: drivers/qmimodem/qmibridge.c:ask_qmi() READ: QMI QMUX:#012QMI   length  = 33#012QMI   flags   = 0x80#012QMI   service = "nas"#012QMI   client  = 2#012QMI QMI:#012
QMI   flags       = "indication"#012QMI   transaction = 0#012QMI   tlv_length  = 21#012QMI   message     = "Serving System" (0x0024)#012QMI TLV:#012QMI   type       = "Detailed Service Status" (0x22)#012QMI   len
gth     = 5#012QMI   value      = 00:01:00:01:00#012QMI   translated = [ status = 'none' capability = 'cs' hdr_status = 'none' hdr_hybrid = 'yes' forbidden = 'no' ]#012QMI TLV:#012QMI   type       = "Data Service
 Capability" (0x11)#012QMI   length     = 1#012QMI   value      = 00#012QMI   translated = {}#012QMI TLV:#012QMI   type       = "Serving System" (0x01)#012QMI   length     = 6#012QMI   value      = 02:00:00:00:01
:00#012QMI   translated = [ registration_state = 'not-registered-searching' cs_attach_state = 'unknown' ps_attach_state = 'unknown' selected_network = 'unknown' radio_interfaces = '{ [0] = 'none '}' ]
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: QMI:     NAS_ind msg=36 len=21 [client=2,type=4,tid=0,len=33]
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: QMI:        {type=34,len=5} {type=17,len=1} {type=1,len=6}
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: drivers/qmimodem/network-registration.c:ss_info_notify()
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: drivers/qmimodem/network-registration.c:extract_ss_info()
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: drivers/qmimodem/network-registration.c:extract_ss_info() serving system status 2
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: drivers/qmimodem/network-registration.c:extract_ss_info() radio in use 0
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: drivers/qmimodem/network-registration.c:extract_ss_info() lac -1 cellid -1 tech -1
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: src/network.c:ofono_netreg_status_notify() /sierra_1 status 2 tech -1 lac -1 ci -1
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: src/network.c:current_operator_callback() 0x5587ec3497d0, (nil)
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: Aborting (signal 11) [/root/ofono/src/ofonod]
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: ++++++++ backtrace ++++++++
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: #0  0x7ffb51785030 in /lib/x86_64-linux-gnu/libc.so.6
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: #1  0x5587eb0156b4 in /root/ofono/src/ofonod
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: #2  0x5587eb015de8 in /root/ofono/src/ofonod
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: #3  0x5587eaf94cd9 in /root/ofono/src/ofonod
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: #4  0x5587eaf8f5bf in /root/ofono/src/ofonod
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: #5  0x5587eaf8f6a1 in /root/ofono/src/ofonod
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: #6  0x5587eaf8f84c in /root/ofono/src/ofonod
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: #7  0x5587eaf8fa6a in /root/ofono/src/ofonod
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: #8  0x7ffb5234f6aa in /lib/x86_64-linux-gnu/libglib-2.0.so.0
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: #9  0x7ffb5234fa60 in /lib/x86_64-linux-gnu/libglib-2.0.so.0
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: #10 0x7ffb5234fd82 in /lib/x86_64-linux-gnu/libglib-2.0.so.0
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: #11 0x5587eb00a14d in /root/ofono/src/ofonod
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: #12 0x7ffb517722b1 in /lib/x86_64-linux-gnu/libc.so.6
Sep  7 20:45:53 osmo-gsm-tester-rnd ofonod[5861]: +++++++++++++++++++++++++++
Sep  7 20:45:53 osmo-gsm-tester-rnd systemd[1]: ofono.service: Main process exited, code=exited, status=1/FAILURE
Sep  7 20:45:53 osmo-gsm-tester-rnd systemd[1]: ofono.service: Unit entered failed state.
Sep  7 20:45:53 osmo-gsm-tester-rnd systemd[1]: ofono.service: Failed with result 'exit-code'.
Sep  7 20:45:54 osmo-gsm-tester-rnd kernel: [1510612.838601] device eth1 left promiscuous mode
Sep  7 20:45:56 osmo-gsm-tester-rnd systemd[1]: ofono.service: Service hold-off time over, scheduling restart.
Sep  7 20:45:56 osmo-gsm-tester-rnd systemd[1]: Stopped Telephony service.

jenkins job log:
- success
- failure between end of trx-b200 and start of sysmocell5000 tests
- success again a couple of tests later

---------------------------------------------------------------------
trial-78 aoip_sms:trx-b200
---------------------------------------------------------------------
20:44:57.742171 tst                aoip_sms:trx-b200: reserving resources in /var/tmp/osmo-gsm-tester/state ...
20:44:57.771767 tst                aoip_sms:trx-b200: Reserving 1 x bts (candidates: 3)
20:44:57.799021 tst                aoip_sms:trx-b200: Reserving 5 x ip_address (candidates: 5)
20:44:57.837420 tst                aoip_sms:trx-b200: Reserving 2 x modem (candidates: 4)

----------------------------------------------
trial-78 aoip_sms:trx-b200 mo_mt_sms.py
----------------------------------------------

20:44:58.015155 tst                aoip_sms:trx-b200: Using 1 x ip_address (candidates: 5)
20:44:58.115515 tst                aoip_sms:trx-b200: Using 1 x bts (candidates: 1)
20:44:58.243326 tst                aoip_sms:trx-b200: Using 1 x ip_address (candidates: 5)
20:44:58.345054 tst                aoip_sms:trx-b200: Using 1 x ip_address (candidates: 5)
20:44:58.446011 tst                aoip_sms:trx-b200: Using 1 x ip_address (candidates: 5)
20:44:58.547658 tst                aoip_sms:trx-b200: Using 1 x ip_address (candidates: 5)
20:44:58.647559 tst                aoip_sms:trx-b200: Using 1 x modem (candidates: 2)
20:44:58.789046 tst                aoip_sms:trx-b200: Using 1 x modem (candidates: 2)
20:44:58.911696 run              osmo-hlr_10.42.42.2: Starting osmo-hlr

20:44:59.280577 run          create_hlr_db(pid=6478): Launched
20:44:59.305155 bus                        /sierra_1: Setting Powered False

20:45:00.380600 run          create_hlr_db(pid=6478): Terminated: ok {rc=0}
20:45:00.513828 run pcap-recorder_eth1:0(filters='host 10.42.42.2'): Recording pcap /home/jenkins/workspace/osmo-gsm-tester_manual-run-all/trial-78/run.2017-09-07_20-41-03/aoip_sms:trx-b200/mo_mt_sms.py/osmo-hlr_10.42.42.2/pcap host 10.42.42.2
20:45:00.602026 run pcap-recorder_eth1:0(filters='host 10.42.42.2')(pid=6490): Launched
20:45:00.705854 run    osmo-hlr_10.42.42.2(pid=6491): Launched
20:45:00.725748 run              osmo-stp_10.42.42.6: Starting osmo-stp
20:45:01.053640 run    osmo-stp_10.42.42.6(pid=6492): Launched
20:45:01.072406 run              osmo-msc_10.42.42.4: Starting osmo-msc

20:45:01.439501 run pcap-recorder_eth1:2(filters='host 10.42.42.4 and port not 22'): Recording pcap /home/jenkins/workspace/osmo-gsm-tester_manual-run-all/trial-78/run.2017-09-07_20-41-03/aoip_sms:trx-b200/mo_mt_sms.py/osmo-msc_10.42.42.4/pcap host 10.42.42.4 and port not 22
20:45:01.524545 run pcap-recorder_eth1:2(filters='host 10.42.42.4 and port not 22')(pid=6503): Launched
20:45:01.627542 run    osmo-msc_10.42.42.4(pid=6504): Launched
20:45:01.647886 run           osmo-mgcpgw_10.42.42.3: Starting osmo-mgcpgw
20:45:02.033090 run pcap-recorder_eth1:1(filters='host 10.42.42.3 and port not 22'): Recording pcap /home/jenkins/workspace/osmo-gsm-tester_manual-run-all/trial-78/run.2017-09-07_20-41-03/aoip_sms:trx-b200/mo_mt_sms.py/osmo-mgcpgw_10.42.42.3/pcap host 10.42.42.3 and port not 22
20:45:02.120906 run pcap-recorder_eth1:1(filters='host 10.42.42.3 and port not 22')(pid=6521): Launched

20:45:02.224639 run osmo-mgcpgw_10.42.42.3(pid=6522): Launched
20:45:02.243408 run              osmo-bsc_10.42.42.5: Starting osmo-bsc
20:45:02.903262 run pcap-recorder_eth1:3(filters='host 10.42.42.5 and port not 22'): Recording pcap /home/jenkins/workspace/osmo-gsm-tester_manual-run-all/trial-78/run.2017-09-07_20-41-03/aoip_sms:trx-b200/mo_mt_sms.py/osmo-bsc_10.42.42.5/pcap host 10.42.42.5 and port not 22
20:45:02.991251 run pcap-recorder_eth1:3(filters='host 10.42.42.5 and port not 22')(pid=6533): Launched
20:45:03.094558 run    osmo-bsc_10.42.42.5(pid=6534): Launched
20:45:03.113666 run                     osmo-bts-trx: Starting to connect to osmo-bsc_10.42.42.5

20:45:03.436407 run               osmo-trx(pid=6535): Launched
20:45:03.455278 run                     osmo-bts-trx: Waiting for osmo-trx to start up...

20:45:11.583548 run           osmo-bts-trx(pid=6561): Launched
20:45:11.617773 run              osmo-hlr_10.42.42.2: Add subscriber {algo=1, imsi='901700000009031', msisdn='26968', subscriber_id=1}
20:45:11.674489 run              osmo-hlr_10.42.42.2: Add subscriber {algo=1, imsi='901700000009029', msisdn='26969', subscriber_id=2}
20:45:11.758856 bus                        /sierra_1: Setting Powered True
20:45:11.990141 bus                        /sierra_1: Setting Online True

20:45:14.667116 tst                        /sierra_1: Connect to ('901', '70')
20:45:14.784240 bus                        /sierra_2: Setting Powered True
20:45:15.076064 bus                        /sierra_2: Setting Online True

20:45:18.083881 tst                        /sierra_2: Already registered with ('901', '70')
20:45:18.122451 tst                        /sierra_1: Manufacturer: 'Sierra Wireless, Incorporated', Model: 'MC7304', Revision: 'SWI9X15C_06.03.32.04 r28324 CNSHZ-AR-BUILD 2015/05/25 01:09:15'
20:45:18.160322 tst                        /sierra_2: Manufacturer: 'Sierra Wireless, Incorporated', Model: 'MC7304', Revision: 'SWI9X15C_06.03.32.04 r28324 CNSHZ-AR-BUILD 2015/05/25 01:09:15'
20:45:18.192523 tst                  mo_mt_sms.py:32: waiting for modems to attach...

20:45:22.664844 tst                        /sierra_1: Registering with operator /sierra_1/operator/90170 ('901', '70')

20:45:26.358976 tst                        /sierra_1: sending sms to MSISDN 26969 {sms='message nr. 4, from /sierra_1, to /sierra_2, from 26968, to 26969'}

20:45:36.415420 tst                        /sierra_2: Incoming SMS: 'message nr. 4, from /sierra_1, to /sierra_2, from 26968, to 26969'
20:45:36.482219 tst                        /sierra_2: SMS received as expected: 'message nr. 4, from /sierra_1, to /sierra_2, from 26968, to 26969'

20:45:36.529288 tst                     mo_mt_sms.py: Test passed (38.5 sec)
20:45:36.626107 run pcap-recorder_eth1:0(filters='host 10.42.42.2')(pid=6490): Terminating (SIGINT)
20:45:36.814918 run pcap-recorder_eth1:0(filters='host 10.42.42.2')(pid=6490): Terminated: ok {rc=0}
20:45:36.824055 run    osmo-hlr_10.42.42.2(pid=6491): Terminating (SIGINT)
20:45:37.016174 run    osmo-hlr_10.42.42.2(pid=6491): Terminated: ok {rc=0}
20:45:37.023072 run    osmo-stp_10.42.42.6(pid=6492): Terminating (SIGINT)
20:45:37.209878 run    osmo-stp_10.42.42.6(pid=6492): Terminated: ok {rc=0}
20:45:37.216727 run pcap-recorder_eth1:2(filters='host 10.42.42.4 and port not 22')(pid=6503): Terminating (SIGINT)
20:45:37.404377 run pcap-recorder_eth1:2(filters='host 10.42.42.4 and port not 22')(pid=6503): Terminated: ok {rc=0}
20:45:37.411382 run    osmo-msc_10.42.42.4(pid=6504): Terminating (SIGINT)

20:45:40.829365 run    osmo-msc_10.42.42.4(pid=6504): Terminated: ok {rc=0}
20:45:40.837241 run pcap-recorder_eth1:1(filters='host 10.42.42.3 and port not 22')(pid=6521): Terminating (SIGINT)
20:45:41.027450 run pcap-recorder_eth1:1(filters='host 10.42.42.3 and port not 22')(pid=6521): Terminated: ok {rc=0}
20:45:41.038855 run osmo-mgcpgw_10.42.42.3(pid=6522): Terminating (SIGINT)
20:45:41.233406 run osmo-mgcpgw_10.42.42.3(pid=6522): Terminated {rc=-2}
20:45:41.240627 run pcap-recorder_eth1:3(filters='host 10.42.42.5 and port not 22')(pid=6533): Terminating (SIGINT)
20:45:41.430413 run pcap-recorder_eth1:3(filters='host 10.42.42.5 and port not 22')(pid=6533): Terminated: ok {rc=0}
20:45:41.438241 run    osmo-bsc_10.42.42.5(pid=6534): Terminating (SIGINT)

20:45:44.854976 run    osmo-bsc_10.42.42.5(pid=6534): Terminated: ok {rc=0}
20:45:44.860500 run               osmo-trx(pid=6535): Terminating (SIGINT)
20:45:45.044675 run               osmo-trx(pid=6535): Terminated: ok {rc=0}
20:45:45.049926 run           osmo-bts-trx(pid=6561): Terminating (SIGINT)

20:45:47.743863 run           osmo-bts-trx(pid=6561): Terminated {rc=42}
20:45:47.762464 bus                        /sierra_2: Setting Powered False

20:45:48.655585 bus                        /sierra_2: Setting Powered False
20:45:48.676234 bus                        /sierra_1: Setting Powered False

---------------------------------------------------------------------
trial-78 aoip_sms:trx-b200 PASS
---------------------------------------------------------------------

---------------------------------------------------------------------
trial-78 sms:trx-sysmocell5000
---------------------------------------------------------------------
20:45:49.781151 tst            sms:trx-sysmocell5000: reserving resources in /var/tmp/osmo-gsm-tester/state ...
20:45:49.812134 tst            sms:trx-sysmocell5000: Reserving 1 x bts (candidates: 3)
20:45:49.838831 tst            sms:trx-sysmocell5000: Reserving 1 x ip_address (candidates: 5)
20:45:49.854213 tst            sms:trx-sysmocell5000: Reserving 2 x modem (candidates: 4)

----------------------------------------------
trial-78 sms:trx-sysmocell5000 mo_mt_sms.py
----------------------------------------------
20:45:49.992371 tst            sms:trx-sysmocell5000: Using 1 x ip_address (candidates: 1)

20:45:50.085864 tst            sms:trx-sysmocell5000: Using 1 x bts (candidates: 1)
20:45:50.203613 tst            sms:trx-sysmocell5000: Using 1 x modem (candidates: 2)
20:45:50.334905 tst            sms:trx-sysmocell5000: Using 1 x modem (candidates: 2)
20:45:50.451935 tst                   mo_mt_sms.py:9: start nitb and bts...
20:45:50.581356 run             osmo-nitb_10.42.42.2: Starting osmo-nitb

20:45:51.268307 run pcap-recorder_eth1:0(filters='host 10.42.42.2 and port not 22'): Recording pcap /home/jenkins/workspace/osmo-gsm-tester_manual-run-all/trial-78/run.2017-09-07_20-41-03/sms:trx-sysmocell5000/mo_mt_sms.py/osmo-nitb_10.42.42.2/pcap host 10.42.42.2 and port not 22
20:45:51.357050 run pcap-recorder_eth1:0(filters='host 10.42.42.2 and port not 22')(pid=6595): Launched
20:45:51.463843 run   osmo-nitb_10.42.42.2(pid=6596): Launched
20:45:51.485210 run                     osmo-bts-trx: Starting to connect to osmo-nitb_10.42.42.2
20:45:51.821173 run           osmo-bts-trx(pid=6597): Launched
20:45:51.858629 run             osmo-nitb_10.42.42.2: Add subscriber {imsi='901700000009031', msisdn='26970'}
20:45:52.047190 run             osmo-nitb_10.42.42.2: Add subscriber {imsi='901700000009029', msisdn='26971'}

20:45:52.262196 bus                        /sierra_1: Setting Powered False
20:45:52.312014 bus                        /sierra_1: Setting Powered True
20:45:52.534097 bus                        /sierra_1: Setting Online True

20:45:54.871231 tst                  mo_mt_sms.py:17: ERR: Error: g-dbus-error-quark: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.ofono was not provided by any .service files (2)  [trial-78↪sms:trx-sysmocell5000↪mo_mt_sms.py:17]
20:45:54.885420 tst                  mo_mt_sms.py:17: Test FAILED (4.9 sec)
20:45:54.894241 run pcap-recorder_eth1:0(filters='host 10.42.42.2 and port not 22')(pid=6595): Terminating (SIGINT)
20:45:55.074138 run pcap-recorder_eth1:0(filters='host 10.42.42.2 and port not 22')(pid=6595): Terminated: ok {rc=0}
20:45:55.079310 run   osmo-nitb_10.42.42.2(pid=6596): Terminating (SIGINT)

20:45:58.497055 run   osmo-nitb_10.42.42.2(pid=6596): Terminated: ok {rc=0}
20:45:58.502179 run           osmo-bts-trx(pid=6597): Terminating (SIGINT)

20:46:01.197342 run           osmo-bts-trx(pid=6597): Terminated {rc=42}
20:46:01.207665 bus                        /sierra_2: Setting Powered False
20:46:01.217872 bus                        /sierra_2: ERR: Error: g-dbus-error-quark: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.ofono was not provided by any .service files (2)  [trial-78↪sms:trx-sysmocell5000↪/sierra_2↪/sierra_2]
20:46:01.229345 bus                        /sierra_1: Setting Powered False
20:46:01.238624 bus                        /sierra_1: ERR: Error: g-dbus-error-quark: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.ofono was not provided by any .service files (2)  [trial-78↪sms:trx-sysmocell5000↪/sierra_1↪/sierra_1]

---------------------------------------------------------------------
trial-78 sms:trx-sysmocell5000 FAIL
---------------------------------------------------------------------

---------------------------------------------------------------------
trial-78 aoip_sms:trx-sysmocell5000
---------------------------------------------------------------------
20:46:01.935898 tst       aoip_sms:trx-sysmocell5000: reserving resources in /var/tmp/osmo-gsm-tester/state ...
20:46:01.966883 tst       aoip_sms:trx-sysmocell5000: Reserving 1 x bts (candidates: 3)
20:46:01.993395 tst       aoip_sms:trx-sysmocell5000: Reserving 5 x ip_address (candidates: 5)
20:46:02.032507 tst       aoip_sms:trx-sysmocell5000: Reserving 2 x modem (candidates: 4)

----------------------------------------------
trial-78 aoip_sms:trx-sysmocell5000 mo_mt_sms.py
----------------------------------------------
20:46:02.212376 tst       aoip_sms:trx-sysmocell5000: Using 1 x ip_address (candidates: 5)
20:46:02.313382 tst       aoip_sms:trx-sysmocell5000: Using 1 x bts (candidates: 1)
20:46:02.441737 tst       aoip_sms:trx-sysmocell5000: Using 1 x ip_address (candidates: 5)

20:46:02.545636 tst       aoip_sms:trx-sysmocell5000: Using 1 x ip_address (candidates: 5)
20:46:02.640614 tst       aoip_sms:trx-sysmocell5000: Using 1 x ip_address (candidates: 5)
20:46:02.734920 tst       aoip_sms:trx-sysmocell5000: Using 1 x ip_address (candidates: 5)
20:46:02.827871 tst       aoip_sms:trx-sysmocell5000: Using 1 x modem (candidates: 2)
20:46:02.916390 tst                  mo_mt_sms.py:10: ERR: Error: g-dbus-error-quark: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.ofono was not provided by any .service files (2)  [trial-78↪aoip_sms:trx-sysmocell5000↪mo_mt_sms.py:10]
20:46:02.928492 tst                  mo_mt_sms.py:10: Test FAILED (0.7 sec)
---------------------------------------------------------------------
trial-78 aoip_sms:trx-sysmocell5000 FAIL
---------------------------------------------------------------------

---------------------------------------------------------------------
trial-78 smpp
---------------------------------------------------------------------
20:46:03.066705 tst                             smpp: reserving resources in /var/tmp/osmo-gsm-tester/state ...
20:46:03.092392 tst                             smpp: Reserving 1 x bts (candidates: 3)
20:46:03.116758 tst                             smpp: Reserving 1 x ip_address (candidates: 5)
20:46:03.134623 tst                             smpp: Reserving 1 x modem (candidates: 4)

----------------------------------------------
trial-78 smpp esme_connect_policy_acceptall.py
----------------------------------------------
20:46:03.254190 tst                             smpp: Using 1 x ip_address (candidates: 1)
20:46:03.350554 tst                             smpp: using MSISDN 26972
20:46:03.369289 run             osmo-nitb_10.42.42.2: Starting osmo-nitb

20:46:03.554516 bus                        /sierra_1: Setting Powered False
Exception ignored in: <bound method ModemDbusInteraction.__del__ of /sierra_1>
Traceback (most recent call last):
  File "/home/jenkins/workspace/osmo-gsm-tester_manual-run-all/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 185, in __del__
    self.cleanup()
  File "/home/jenkins/workspace/osmo-gsm-tester_manual-run-all/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 179, in cleanup
    self.set_powered(False)
  File "/home/jenkins/workspace/osmo-gsm-tester_manual-run-all/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 313, in set_powered
    self.set_bool('Powered', powered)
  File "/home/jenkins/workspace/osmo-gsm-tester_manual-run-all/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 308, in set_bool
    self.interface(iface).SetProperty(name, Variant('b', val))
  File "/home/jenkins/workspace/osmo-gsm-tester_manual-run-all/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 197, in interface
    return self.dbus_obj()[interface_name]
  File "/home/jenkins/workspace/osmo-gsm-tester_manual-run-all/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 192, in dbus_obj
    self._dbus_obj = self.get_new_dbus_obj()
  File "/home/jenkins/workspace/osmo-gsm-tester_manual-run-all/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 188, in get_new_dbus_obj
    return systembus_get(self.modem_path)
  File "/home/jenkins/workspace/osmo-gsm-tester_manual-run-all/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 85, in systembus_get
    return bus.get('org.ofono', path)
  File "/usr/local/lib/python3.5/dist-packages/pydbus/proxy.py", line 47, in get
    0, timeout_to_glib(timeout), None)
GLib.Error: g-dbus-error-quark: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.ofono was not provided by any .service files (2)
20:46:03.823855 run pcap-recorder_eth1:0(filters='host 10.42.42.2 and port not 22'): Recording pcap /home/jenkins/workspace/osmo-gsm-tester_manual-run-all/trial-78/run.2017-09-07_20-41-03/smpp/esme_connect_policy_acceptall.py/osmo-nitb_10.42.42.2/pcap host 10.42.42.2 and port not 22
20:46:03.911806 run pcap-recorder_eth1:0(filters='host 10.42.42.2 and port not 22')(pid=6624): Launched
20:46:04.016429 run   osmo-nitb_10.42.42.2(pid=6625): Launched
20:46:04.040036 tst esme_connect_policy_acceptall.py:22: Test connect with non-empty values in system_id and password
20:46:04.239485 tst                       esme-26972: Connected and bound successfully to foo (10.42.42.2:2775). Starting to listen.
20:46:04.261301 tst esme_connect_policy_acceptall.py:28: Test connect with empty values in system_id and password
20:46:04.409464 tst                       esme-26972: Connected and bound successfully to  (10.42.42.2:2775). Starting to listen.
20:46:04.416114 tst esme_connect_policy_acceptall.py: Test passed (1.2 sec)
20:46:04.466455 run pcap-recorder_eth1:0(filters='host 10.42.42.2 and port not 22')(pid=6624): Terminating (SIGINT)

20:46:04.646539 run pcap-recorder_eth1:0(filters='host 10.42.42.2 and port not 22')(pid=6624): Terminated: ok {rc=0}
20:46:04.651465 run   osmo-nitb_10.42.42.2(pid=6625): Terminating (SIGINT)

20:46:08.068643 run   osmo-nitb_10.42.42.2(pid=6625): Terminated: ok {rc=0}

----------------------------------------------
trial-78 smpp esme_connect_policy_closed.py
----------------------------------------------
20:46:08.111797 tst                             smpp: Using 1 x ip_address (candidates: 1)
20:46:08.205968 tst                             smpp: using MSISDN 26973
20:46:08.238036 tst                             smpp: using MSISDN 26974
20:46:08.256948 run             osmo-nitb_10.42.42.2: Starting osmo-nitb
20:46:08.626598 run pcap-recorder_eth1:0(filters='host 10.42.42.2 and port not 22'): Recording pcap /home/jenkins/workspace/osmo-gsm-tester_manual-run-all/trial-78/run.2017-09-07_20-41-03/smpp/esme_connect_policy_closed.py/osmo-nitb_10.42.42.2/pcap host 10.42.42.2 and port not 22

20:46:08.715902 run pcap-recorder_eth1:0(filters='host 10.42.42.2 and port not 22')(pid=6640): Launched
20:46:08.821380 run   osmo-nitb_10.42.42.2(pid=6641): Launched
20:46:08.846196 tst esme_connect_policy_closed.py:26: Test with correct credentials (no password)
20:46:09.029462 tst                       esme-26974: Connected and bound successfully to esme-26974 (10.42.42.2:2775). Starting to listen.
20:46:09.050971 tst esme_connect_policy_closed.py:30: Test with correct credentials (no password, non empty)
20:46:09.197429 tst                       esme-26974: Connected and bound successfully to esme-26974 (10.42.42.2:2775). Starting to listen.
20:46:09.219082 tst esme_connect_policy_closed.py:35: Test with correct credentials
20:46:09.365654 tst                       esme-26973: Connected and bound successfully to esme-26973 (10.42.42.2:2775). Starting to listen.
20:46:09.387046 tst esme_connect_policy_closed.py:39: Test with bad password, checking for failure
20:46:09.557756 tst esme_connect_policy_closed.py:46: Test with bad system_id, checking for failure

20:46:09.709260 tst    esme_connect_policy_closed.py: Test passed (1.6 sec)
20:46:09.758785 run pcap-recorder_eth1:0(filters='host 10.42.42.2 and port not 22')(pid=6640): Terminating (SIGINT)
20:46:09.939108 run pcap-recorder_eth1:0(filters='host 10.42.42.2 and port not 22')(pid=6640): Terminated: ok {rc=0}
20:46:09.943500 run   osmo-nitb_10.42.42.2(pid=6641): Terminating (SIGINT)

20:46:13.360408 run   osmo-nitb_10.42.42.2(pid=6641): Terminated: ok {rc=0}

----------------------------------------------
trial-78 smpp esme_ms_sms_storeforward.py
----------------------------------------------
20:46:13.404352 tst                             smpp: Using 1 x ip_address (candidates: 1)
20:46:13.503035 tst                             smpp: Using 1 x bts (candidates: 1)
20:46:13.619473 tst                             smpp: Using 1 x modem (candidates: 1)
20:46:13.707709 tst   esme_ms_sms_storeforward.py:17: ERR: Error: g-dbus-error-quark: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.ofono was not provided by any .service files (2)  [trial-78↪smpp↪esme_ms_sms_storeforward.py:17]
20:46:13.719648 tst   esme_ms_sms_storeforward.py:17: Test FAILED (0.3 sec)

----------------------------------------------
trial-78 smpp esme_ms_sms_transaction.py
----------------------------------------------
20:46:13.765455 tst                             smpp: Using 1 x ip_address (candidates: 1)

20:46:13.859506 tst                             smpp: Using 1 x bts (candidates: 1)
20:46:13.976122 tst                             smpp: Using 1 x modem (candidates: 1)
20:46:14.063733 tst    esme_ms_sms_transaction.py:15: ERR: Error: g-dbus-error-quark: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.ofono was not provided by any .service files (2)  [trial-78↪smpp↪esme_ms_sms_transaction.py:15]
20:46:14.075760 tst    esme_ms_sms_transaction.py:15: Test FAILED (0.3 sec)
---------------------------------------------------------------------
trial-78 smpp FAIL
---------------------------------------------------------------------

---------------------------------------------------------------------
trial-78 aoip_smpp
---------------------------------------------------------------------
20:46:14.156838 tst                        aoip_smpp: reserving resources in /var/tmp/osmo-gsm-tester/state ...
20:46:14.182151 tst                        aoip_smpp: Reserving 1 x bts (candidates: 3)
20:46:14.207163 tst                        aoip_smpp: Reserving 5 x ip_address (candidates: 5)
20:46:14.246075 tst                        aoip_smpp: Reserving 1 x modem (candidates: 4)

----------------------------------------------
trial-78 aoip_smpp esme_connect_policy_acceptall.py
----------------------------------------------
20:46:14.395382 tst                        aoip_smpp: Using 1 x ip_address (candidates: 5)
20:46:14.497809 tst                        aoip_smpp: Using 1 x bts (candidates: 1)
20:46:14.624603 tst                        aoip_smpp: Using 1 x ip_address (candidates: 5)
20:46:14.725805 tst                        aoip_smpp: Using 1 x ip_address (candidates: 5)
20:46:14.823249 tst                        aoip_smpp: using MSISDN 26975
20:46:14.842062 run              osmo-hlr_10.42.42.2: Starting osmo-hlr

20:46:14.945965 bus                        /sierra_1: Setting Powered False
Exception ignored in: <bound method ModemDbusInteraction.__del__ of /sierra_1>
Traceback (most recent call last):
  File "/home/jenkins/workspace/osmo-gsm-tester_manual-run-all/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 185, in __del__
    self.cleanup()
  File "/home/jenkins/workspace/osmo-gsm-tester_manual-run-all/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 179, in cleanup
    self.set_powered(False)
  File "/home/jenkins/workspace/osmo-gsm-tester_manual-run-all/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 313, in set_powered
    self.set_bool('Powered', powered)
  File "/home/jenkins/workspace/osmo-gsm-tester_manual-run-all/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 308, in set_bool
    self.interface(iface).SetProperty(name, Variant('b', val))
  File "/home/jenkins/workspace/osmo-gsm-tester_manual-run-all/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 197, in interface
    return self.dbus_obj()[interface_name]
  File "/home/jenkins/workspace/osmo-gsm-tester_manual-run-all/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 192, in dbus_obj
    self._dbus_obj = self.get_new_dbus_obj()
  File "/home/jenkins/workspace/osmo-gsm-tester_manual-run-all/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 188, in get_new_dbus_obj
    return systembus_get(self.modem_path)
  File "/home/jenkins/workspace/osmo-gsm-tester_manual-run-all/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 85, in systembus_get
    return bus.get('org.ofono', path)
  File "/usr/local/lib/python3.5/dist-packages/pydbus/proxy.py", line 47, in get
    0, timeout_to_glib(timeout), None)
GLib.Error: g-dbus-error-quark: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.ofono was not provided by any .service files (2)
20:46:14.989234 bus                        /sierra_1: Setting Powered False
Exception ignored in: <bound method ModemDbusInteraction.__del__ of /sierra_1>
Traceback (most recent call last):
  File "/home/jenkins/workspace/osmo-gsm-tester_manual-run-all/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 185, in __del__
    self.cleanup()
  File "/home/jenkins/workspace/osmo-gsm-tester_manual-run-all/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 179, in cleanup
    self.set_powered(False)
  File "/home/jenkins/workspace/osmo-gsm-tester_manual-run-all/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 313, in set_powered
    self.set_bool('Powered', powered)
  File "/home/jenkins/workspace/osmo-gsm-tester_manual-run-all/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 308, in set_bool
    self.interface(iface).SetProperty(name, Variant('b', val))
  File "/home/jenkins/workspace/osmo-gsm-tester_manual-run-all/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 197, in interface
    return self.dbus_obj()[interface_name]
  File "/home/jenkins/workspace/osmo-gsm-tester_manual-run-all/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 192, in dbus_obj
    self._dbus_obj = self.get_new_dbus_obj()
  File "/home/jenkins/workspace/osmo-gsm-tester_manual-run-all/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 188, in get_new_dbus_obj
    return systembus_get(self.modem_path)
  File "/home/jenkins/workspace/osmo-gsm-tester_manual-run-all/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 85, in systembus_get
    return bus.get('org.ofono', path)
  File "/usr/local/lib/python3.5/dist-packages/pydbus/proxy.py", line 47, in get
    0, timeout_to_glib(timeout), None)
GLib.Error: g-dbus-error-quark: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.ofono was not provided by any .service files (2)
20:46:15.281905 run          create_hlr_db(pid=6646): Launched

20:46:16.327151 run          create_hlr_db(pid=6646): Terminated: ok {rc=0}
20:46:16.464921 run pcap-recorder_eth1:0(filters='host 10.42.42.2'): Recording pcap /home/jenkins/workspace/osmo-gsm-tester_manual-run-all/trial-78/run.2017-09-07_20-41-03/aoip_smpp/esme_connect_policy_acceptall.py/osmo-hlr_10.42.42.2/pcap host 10.42.42.2
20:46:16.554190 run pcap-recorder_eth1:0(filters='host 10.42.42.2')(pid=6658): Launched
20:46:16.658723 run    osmo-hlr_10.42.42.2(pid=6659): Launched
20:46:16.679288 run              osmo-msc_10.42.42.4: Starting osmo-msc

20:46:17.044823 run pcap-recorder_eth1:2(filters='host 10.42.42.4 and port not 22'): Recording pcap /home/jenkins/workspace/osmo-gsm-tester_manual-run-all/trial-78/run.2017-09-07_20-41-03/aoip_smpp/esme_connect_policy_acceptall.py/osmo-msc_10.42.42.4/pcap host 10.42.42.4 and port not 22
20:46:17.134911 run pcap-recorder_eth1:2(filters='host 10.42.42.4 and port not 22')(pid=6672): Launched
20:46:17.258182 run    osmo-msc_10.42.42.4(pid=6678): Launched
20:46:17.281028 run           osmo-mgcpgw_10.42.42.3: Starting osmo-mgcpgw
20:46:17.669233 run pcap-recorder_eth1:1(filters='host 10.42.42.3 and port not 22'): Recording pcap /home/jenkins/workspace/osmo-gsm-tester_manual-run-all/trial-78/run.2017-09-07_20-41-03/aoip_smpp/esme_connect_policy_acceptall.py/osmo-mgcpgw_10.42.42.3/pcap host 10.42.42.3 and port not 22
20:46:17.786855 run pcap-recorder_eth1:1(filters='host 10.42.42.3 and port not 22')(pid=6698): Launched
20:46:17.887145 run osmo-mgcpgw_10.42.42.3(pid=6699): Launched
20:46:17.908363 tst esme_connect_policy_acceptall.py:27: Test connect with non-empty values in system_id and password

20:46:18.049621 tst                       esme-26975: Connected and bound successfully to foo (10.42.42.4:2775). Starting to listen.
20:46:18.069964 tst esme_connect_policy_acceptall.py:33: Test connect with empty values in system_id and password
20:46:18.214944 tst                       esme-26975: Connected and bound successfully to  (10.42.42.4:2775). Starting to listen.
20:46:18.221412 tst esme_connect_policy_acceptall.py: Test passed (3.9 sec)
20:46:18.286445 run pcap-recorder_eth1:0(filters='host 10.42.42.2')(pid=6658): Terminating (SIGINT)
20:46:18.467190 run pcap-recorder_eth1:0(filters='host 10.42.42.2')(pid=6658): Terminated: ok {rc=0}
20:46:18.471616 run    osmo-hlr_10.42.42.2(pid=6659): Terminating (SIGINT)
20:46:18.651778 run    osmo-hlr_10.42.42.2(pid=6659): Terminated: ok {rc=0}
20:46:18.658874 run pcap-recorder_eth1:2(filters='host 10.42.42.4 and port not 22')(pid=6672): Terminating (SIGINT)
20:46:18.839345 run pcap-recorder_eth1:2(filters='host 10.42.42.4 and port not 22')(pid=6672): Terminated: ok {rc=0}
20:46:18.844380 run    osmo-msc_10.42.42.4(pid=6678): Terminating (SIGINT)

20:46:22.261072 run    osmo-msc_10.42.42.4(pid=6678): Terminated: ok {rc=0}
20:46:22.266029 run pcap-recorder_eth1:1(filters='host 10.42.42.3 and port not 22')(pid=6698): Terminating (SIGINT)
20:46:22.445132 run pcap-recorder_eth1:1(filters='host 10.42.42.3 and port not 22')(pid=6698): Terminated: ok {rc=0}
20:46:22.449998 run osmo-mgcpgw_10.42.42.3(pid=6699): Terminating (SIGINT)
20:46:22.460659 run osmo-mgcpgw_10.42.42.3(pid=6699): Terminated {rc=-2}

----------------------------------------------
trial-78 aoip_smpp esme_connect_policy_closed.py
----------------------------------------------
20:46:22.505537 tst                        aoip_smpp: Using 1 x ip_address (candidates: 5)
20:46:22.600210 tst                        aoip_smpp: Using 1 x bts (candidates: 1)
20:46:22.718386 tst                        aoip_smpp: Using 1 x ip_address (candidates: 5)
20:46:22.815640 tst                        aoip_smpp: Using 1 x ip_address (candidates: 5)
20:46:22.935611 tst                        aoip_smpp: using MSISDN 26976
20:46:22.971890 tst                        aoip_smpp: using MSISDN 26977
20:46:22.991834 run              osmo-hlr_10.42.42.2: Starting osmo-hlr

20:46:23.322159 run          create_hlr_db(pid=6790): Launched

20:46:24.365505 run          create_hlr_db(pid=6790): Terminated: ok {rc=0}
20:46:24.507163 run pcap-recorder_eth1:0(filters='host 10.42.42.2'): Recording pcap /home/jenkins/workspace/osmo-gsm-tester_manual-run-all/trial-78/run.2017-09-07_20-41-03/aoip_smpp/esme_connect_policy_closed.py/osmo-hlr_10.42.42.2/pcap host 10.42.42.2
20:46:24.598019 run pcap-recorder_eth1:0(filters='host 10.42.42.2')(pid=6813): Launched
20:46:24.708892 run    osmo-hlr_10.42.42.2(pid=6815): Launched
20:46:24.728529 run              osmo-msc_10.42.42.4: Starting osmo-msc
20:46:25.104040 run pcap-recorder_eth1:2(filters='host 10.42.42.4 and port not 22'): Recording pcap /home/jenkins/workspace/osmo-gsm-tester_manual-run-all/trial-78/run.2017-09-07_20-41-03/aoip_smpp/esme_connect_policy_closed.py/osmo-msc_10.42.42.4/pcap host 10.42.42.4 and port not 22
20:46:25.193721 run pcap-recorder_eth1:2(filters='host 10.42.42.4 and port not 22')(pid=6826): Launched

20:46:25.298369 run    osmo-msc_10.42.42.4(pid=6827): Launched
20:46:25.319246 run           osmo-mgcpgw_10.42.42.3: Starting osmo-mgcpgw
20:46:25.705935 run pcap-recorder_eth1:1(filters='host 10.42.42.3 and port not 22'): Recording pcap /home/jenkins/workspace/osmo-gsm-tester_manual-run-all/trial-78/run.2017-09-07_20-41-03/aoip_smpp/esme_connect_policy_closed.py/osmo-mgcpgw_10.42.42.3/pcap host 10.42.42.3 and port not 22
20:46:25.790931 run pcap-recorder_eth1:1(filters='host 10.42.42.3 and port not 22')(pid=6843): Launched
20:46:25.896865 run osmo-mgcpgw_10.42.42.3(pid=6844): Launched
20:46:25.917807 tst esme_connect_policy_closed.py:32: Test with correct credentials (no password)
20:46:26.062664 tst                       esme-26977: Connected and bound successfully to esme-26977 (10.42.42.4:2775). Starting to listen.
20:46:26.083017 tst esme_connect_policy_closed.py:36: Test with correct credentials (no password, non empty)
20:46:26.222872 tst                       esme-26977: Connected and bound successfully to esme-26977 (10.42.42.4:2775). Starting to listen.
20:46:26.243092 tst esme_connect_policy_closed.py:41: Test with correct credentials

20:46:26.379731 tst                       esme-26976: Connected and bound successfully to esme-26976 (10.42.42.4:2775). Starting to listen.
20:46:26.399979 tst esme_connect_policy_closed.py:45: Test with bad password, checking for failure
20:46:26.559769 tst esme_connect_policy_closed.py:52: Test with bad system_id, checking for failure
20:46:26.701106 tst    esme_connect_policy_closed.py: Test passed (4.2 sec)
20:46:26.748610 run pcap-recorder_eth1:0(filters='host 10.42.42.2')(pid=6813): Terminating (SIGINT)
20:46:26.928770 run pcap-recorder_eth1:0(filters='host 10.42.42.2')(pid=6813): Terminated: ok {rc=0}
20:46:26.932966 run    osmo-hlr_10.42.42.2(pid=6815): Terminating (SIGINT)
20:46:27.112106 run    osmo-hlr_10.42.42.2(pid=6815): Terminated: ok {rc=0}
20:46:27.116441 run pcap-recorder_eth1:2(filters='host 10.42.42.4 and port not 22')(pid=6826): Terminating (SIGINT)
20:46:27.296057 run pcap-recorder_eth1:2(filters='host 10.42.42.4 and port not 22')(pid=6826): Terminated: ok {rc=0}
20:46:27.300206 run    osmo-msc_10.42.42.4(pid=6827): Terminating (SIGINT)

20:46:30.719559 run    osmo-msc_10.42.42.4(pid=6827): Terminated: ok {rc=0}
20:46:30.725007 run pcap-recorder_eth1:1(filters='host 10.42.42.3 and port not 22')(pid=6843): Terminating (SIGINT)
20:46:30.910444 run pcap-recorder_eth1:1(filters='host 10.42.42.3 and port not 22')(pid=6843): Terminated: ok {rc=0}
20:46:30.930788 run osmo-mgcpgw_10.42.42.3(pid=6844): Terminating (SIGINT)
20:46:31.110675 run osmo-mgcpgw_10.42.42.3(pid=6844): Terminated {rc=-2}

----------------------------------------------
trial-78 aoip_smpp esme_ms_sms_storeforward.py
----------------------------------------------
20:46:31.161172 tst                        aoip_smpp: Using 1 x ip_address (candidates: 5)
20:46:31.272614 tst                        aoip_smpp: Using 1 x bts (candidates: 1)
20:46:31.414150 tst                        aoip_smpp: Using 1 x ip_address (candidates: 5)

20:46:31.539455 tst                        aoip_smpp: Using 1 x ip_address (candidates: 5)
20:46:31.697546 tst                        aoip_smpp: Using 1 x ip_address (candidates: 5)
20:46:31.825436 tst                        aoip_smpp: Using 1 x ip_address (candidates: 5)
20:46:31.948891 tst                        aoip_smpp: Using 1 x modem (candidates: 1)
20:46:32.127052 tst   esme_ms_sms_storeforward.py:23: ERR: Error: g-dbus-error-quark: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.ofono was not provided by any .service files (2)  [trial-78↪aoip_smpp↪esme_ms_sms_storeforward.py:23]
20:46:32.148632 tst   esme_ms_sms_storeforward.py:23: Test FAILED (1.0 sec)

----------------------------------------------
trial-78 aoip_smpp esme_ms_sms_transaction.py
----------------------------------------------
20:46:32.225708 tst                        aoip_smpp: Using 1 x ip_address (candidates: 5)
20:46:32.331612 tst                        aoip_smpp: Using 1 x bts (candidates: 1)
20:46:32.465638 tst                        aoip_smpp: Using 1 x ip_address (candidates: 5)

20:46:32.565469 tst                        aoip_smpp: Using 1 x ip_address (candidates: 5)
20:46:32.667004 tst                        aoip_smpp: Using 1 x ip_address (candidates: 5)
20:46:32.784059 tst                        aoip_smpp: Using 1 x ip_address (candidates: 5)
20:46:32.879741 tst                        aoip_smpp: Using 1 x modem (candidates: 1)
20:46:32.985542 tst    esme_ms_sms_transaction.py:21: ERR: Error: g-dbus-error-quark: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.ofono was not provided by any .service files (2)  [trial-78↪aoip_smpp↪esme_ms_sms_transaction.py:21]
20:46:32.997934 tst    esme_ms_sms_transaction.py:21: Test FAILED (0.8 sec)
---------------------------------------------------------------------
trial-78 aoip_smpp FAIL
---------------------------------------------------------------------

---------------------------------------------------------------------
trial-78 aoip_encryption
---------------------------------------------------------------------
20:46:33.125464 tst                  aoip_encryption: reserving resources in /var/tmp/osmo-gsm-tester/state ...
20:46:33.158687 tst                  aoip_encryption: Reserving 1 x bts (candidates: 3)
20:46:33.191860 tst                  aoip_encryption: Reserving 5 x ip_address (candidates: 5)
20:46:33.248796 tst                  aoip_encryption: Reserving 1 x modem (candidates: 4)

----------------------------------------------
trial-78 aoip_encryption register_a5_0_authopt.py
----------------------------------------------
20:46:33.436825 tst                  aoip_encryption: Using 1 x ip_address (candidates: 5)

20:46:33.576436 tst                  aoip_encryption: Using 1 x bts (candidates: 1)
20:46:33.705682 tst                  aoip_encryption: Using 1 x ip_address (candidates: 5)
20:46:33.806738 tst                  aoip_encryption: Using 1 x ip_address (candidates: 5)
20:46:33.909541 tst                  aoip_encryption: Using 1 x ip_address (candidates: 5)
20:46:34.010899 tst                  aoip_encryption: Using 1 x ip_address (candidates: 5)
20:46:34.113261 tst                  aoip_encryption: Using 1 x modem (candidates: 1)
20:46:34.237444 tst      register_a5_0_authopt.py:12: start network...
20:46:34.389403 run              osmo-hlr_10.42.42.2: Starting osmo-hlr
20:46:34.472814 bus                        /sierra_1: Setting Powered False
20:46:34.533721 bus                        /sierra_1: Setting Powered False

20:46:34.885931 run          create_hlr_db(pid=7181): Launched

20:46:35.930909 run          create_hlr_db(pid=7181): Terminated: ok {rc=0}
20:46:36.071818 run pcap-recorder_eth1:0(filters='host 10.42.42.2'): Recording pcap /home/jenkins/workspace/osmo-gsm-tester_manual-run-all/trial-78/run.2017-09-07_20-41-03/aoip_encryption/register_a5_0_authopt.py/osmo-hlr_10.42.42.2/pcap host 10.42.42.2
20:46:36.161047 run pcap-recorder_eth1:0(filters='host 10.42.42.2')(pid=7193): Launched
20:46:36.273715 run    osmo-hlr_10.42.42.2(pid=7194): Launched
20:46:36.292814 run              osmo-stp_10.42.42.6: Starting osmo-stp
20:46:36.626702 run    osmo-stp_10.42.42.6(pid=7195): Launched
20:46:36.644014 run              osmo-msc_10.42.42.4: Starting osmo-msc

20:46:37.002607 run pcap-recorder_eth1:2(filters='host 10.42.42.4 and port not 22'): Recording pcap /home/jenkins/workspace/osmo-gsm-tester_manual-run-all/trial-78/run.2017-09-07_20-41-03/aoip_encryption/register_a5_0_authopt.py/osmo-msc_10.42.42.4/pcap host 10.42.42.4 and port not 22
20:46:37.092542 run pcap-recorder_eth1:2(filters='host 10.42.42.4 and port not 22')(pid=7206): Launched
20:46:37.197830 run    osmo-msc_10.42.42.4(pid=7207): Launched
20:46:37.221004 run           osmo-mgcpgw_10.42.42.3: Starting osmo-mgcpgw
20:46:37.610671 run pcap-recorder_eth1:1(filters='host 10.42.42.3 and port not 22'): Recording pcap /home/jenkins/workspace/osmo-gsm-tester_manual-run-all/trial-78/run.2017-09-07_20-41-03/aoip_encryption/register_a5_0_authopt.py/osmo-mgcpgw_10.42.42.3/pcap host 10.42.42.3 and port not 22

20:46:37.699655 run pcap-recorder_eth1:1(filters='host 10.42.42.3 and port not 22')(pid=7218): Launched
20:46:37.804768 run osmo-mgcpgw_10.42.42.3(pid=7219): Launched
20:46:37.824022 run              osmo-bsc_10.42.42.5: Starting osmo-bsc
20:46:38.491441 run pcap-recorder_eth1:3(filters='host 10.42.42.5 and port not 22'): Recording pcap /home/jenkins/workspace/osmo-gsm-tester_manual-run-all/trial-78/run.2017-09-07_20-41-03/aoip_encryption/register_a5_0_authopt.py/osmo-bsc_10.42.42.5/pcap host 10.42.42.5 and port not 22
20:46:38.580421 run pcap-recorder_eth1:3(filters='host 10.42.42.5 and port not 22')(pid=7230): Launched
20:46:38.685849 run    osmo-bsc_10.42.42.5(pid=7231): Launched
20:46:38.705105 run                   osmo-bts-sysmo: Starting sysmoBTS to connect to osmo-bsc_10.42.42.5

20:46:39.040506 run          rm-remote-dir(pid=7232): Launched

20:46:41.087631 run          rm-remote-dir(pid=7232): Terminated: ok {rc=0}
20:46:41.194242 run          mk-remote-dir(pid=7237): Launched

20:46:43.243725 run          mk-remote-dir(pid=7237): Terminated: ok {rc=0}
20:46:43.328625 run   scp-inst-to-sysmobts(pid=7238): Launched

20:46:55.389827 run   scp-inst-to-sysmobts(pid=7238): Terminated: ok {rc=0}
20:46:55.514664 run      mk-remote-run-dir(pid=7240): Launched

20:46:57.561505 run      mk-remote-run-dir(pid=7240): Terminated: ok {rc=0}
20:46:57.650197 run    scp-cfg-to-sysmobts(pid=7241): Launched

20:47:00.700055 run    scp-cfg-to-sysmobts(pid=7241): Terminated: ok {rc=0}
20:47:00.811051 run    reload-dsp-firmware(pid=7243): Launched

20:47:03.856593 run    reload-dsp-firmware(pid=7243): Terminated: ok {rc=0}
20:47:03.955399 run         osmo-bts-sysmo(pid=7244): Launched
20:47:03.978367 tst                        /sierra_1: Manufacturer: None, Model: None, Revision: None
20:47:03.997447 tst      register_a5_0_authopt.py:28: KI changed: 80A37E6FDEA931EAC92FFA5F671EFEAD => 90A37E6FDEA931EAC92FFA5F671EFEAD
20:47:04.142157 run              osmo-hlr_10.42.42.2: Add subscriber {algo=1, imsi='901700000009031', msisdn='26978', subscriber_id=1}
20:47:04.185184 tst      register_a5_0_authopt.py:31: Attempt connection with wrong KI, should work as it is not used...
20:47:04.373633 bus                        /sierra_1: Setting Powered True

20:47:04.846976 bus                        /sierra_1: Setting Online True

20:47:07.908882 tst                        /sierra_1: Connect to ('901', '70')

20:47:21.313133 tst                        /sierra_1: Registering with operator /sierra_1/operator/90170 ('901', '70')

20:47:25.015399 tst         register_a5_0_authopt.py: Test passed (51.6 sec)
20:47:25.063008 run pcap-recorder_eth1:0(filters='host 10.42.42.2')(pid=7193): Terminating (SIGINT)
20:47:25.242703 run pcap-recorder_eth1:0(filters='host 10.42.42.2')(pid=7193): Terminated: ok {rc=0}
20:47:25.247426 run    osmo-hlr_10.42.42.2(pid=7194): Terminating (SIGINT)

20:47:25.426545 run    osmo-hlr_10.42.42.2(pid=7194): Terminated: ok {rc=0}
20:47:25.435387 run    osmo-stp_10.42.42.6(pid=7195): Terminating (SIGINT)
20:47:25.614981 run    osmo-stp_10.42.42.6(pid=7195): Terminated: ok {rc=0}
20:47:25.619575 run pcap-recorder_eth1:2(filters='host 10.42.42.4 and port not 22')(pid=7206): Terminating (SIGINT)
20:47:25.799972 run pcap-recorder_eth1:2(filters='host 10.42.42.4 and port not 22')(pid=7206): Terminated: ok {rc=0}
20:47:25.805044 run    osmo-msc_10.42.42.4(pid=7207): Terminating (SIGINT)

20:47:29.221631 run    osmo-msc_10.42.42.4(pid=7207): Terminated: ok {rc=0}
20:47:29.228850 run pcap-recorder_eth1:1(filters='host 10.42.42.3 and port not 22')(pid=7218): Terminating (SIGINT)
20:47:29.409321 run pcap-recorder_eth1:1(filters='host 10.42.42.3 and port not 22')(pid=7218): Terminated: ok {rc=0}
20:47:29.414164 run osmo-mgcpgw_10.42.42.3(pid=7219): Terminating (SIGINT)
20:47:29.593302 run osmo-mgcpgw_10.42.42.3(pid=7219): Terminated {rc=-2}
20:47:29.598080 run pcap-recorder_eth1:3(filters='host 10.42.42.5 and port not 22')(pid=7230): Terminating (SIGINT)
20:47:29.783752 run pcap-recorder_eth1:3(filters='host 10.42.42.5 and port not 22')(pid=7230): Terminated: ok {rc=0}
20:47:29.789077 run    osmo-bsc_10.42.42.5(pid=7231): Terminating (SIGINT)

20:47:33.205966 run    osmo-bsc_10.42.42.5(pid=7231): Terminated: ok {rc=0}
20:47:33.211266 run         osmo-bts-sysmo(pid=7244): Terminating (SIGINT)
20:47:33.223158 run         osmo-bts-sysmo(pid=7244): Terminated {rc=130}
20:47:33.236627 bus                        /sierra_1: Setting Powered False

#2 Updated by neels 12 days ago

I see massive QMI and ofono logging on syslog, and pespin suggested that maybe this is too much for ofono and responsible for the crashes.
So I disabled the -d and QMI logging on the RnD setup for now, in /etc/systemd/system/ofono.service.
Let's see if the builds are more successful now?

#3 Updated by neels 12 days ago

for the record, a build that has at least one ofono crash is
https://jenkins.osmocom.org/jenkins/job/osmo-gsm-tester_manual-run-all/78/console

the first one after the -d option was removed from ofonod was
https://jenkins.osmocom.org/jenkins/job/osmo-gsm-tester_manual-run-all/79/

#4 Updated by neels 12 days ago

nope, again the same crash at exactly the same place, syslog says:

Sep  7 21:09:58 osmo-gsm-tester-rnd ofonod[8561]: Interface org.ofono.AllowedAccessPoints not found on the interface_list
Sep  7 21:09:58 osmo-gsm-tester-rnd ofonod[8561]: Requested file structure differs from SIM: 6fb7
Sep  7 21:09:59 osmo-gsm-tester-rnd ofonod[8561]: RegisterProfile() replied an error: org.freedesktop.DBus.Error.ServiceUnknown, The name org.bluez was not provided by any .service files
Sep  7 21:09:59 osmo-gsm-tester-rnd ofonod[8561]: RegisterProfile() replied an error: org.freedesktop.DBus.Error.ServiceUnknown, The name org.bluez was not provided by any .service files
Sep  7 21:09:59 osmo-gsm-tester-rnd ofonod[8561]: Aborting (signal 11) [/root/ofono/src/ofonod]
Sep  7 21:09:59 osmo-gsm-tester-rnd ofonod[8561]: ++++++++ backtrace ++++++++
Sep  7 21:09:59 osmo-gsm-tester-rnd ofonod[8561]: #0  0x7f0d9eec9030 in /lib/x86_64-linux-gnu/libc.so.6
Sep  7 21:09:59 osmo-gsm-tester-rnd ofonod[8561]: #1  0x564f6bca46b4 in /root/ofono/src/ofonod
Sep  7 21:09:59 osmo-gsm-tester-rnd ofonod[8561]: #2  0x564f6bca4de8 in /root/ofono/src/ofonod
Sep  7 21:09:59 osmo-gsm-tester-rnd ofonod[8561]: #3  0x564f6bc23cd9 in /root/ofono/src/ofonod
Sep  7 21:09:59 osmo-gsm-tester-rnd ofonod[8561]: #4  0x564f6bc1e5bf in /root/ofono/src/ofonod
Sep  7 21:09:59 osmo-gsm-tester-rnd ofonod[8561]: #5  0x564f6bc1e6a1 in /root/ofono/src/ofonod
Sep  7 21:09:59 osmo-gsm-tester-rnd ofonod[8561]: #6  0x564f6bc1e84c in /root/ofono/src/ofonod
Sep  7 21:09:59 osmo-gsm-tester-rnd ofonod[8561]: #7  0x564f6bc1ea6a in /root/ofono/src/ofonod
Sep  7 21:09:59 osmo-gsm-tester-rnd ofonod[8561]: #8  0x7f0d9fa936aa in /lib/x86_64-linux-gnu/libglib-2.0.so.0
Sep  7 21:09:59 osmo-gsm-tester-rnd ofonod[8561]: #9  0x7f0d9fa93a60 in /lib/x86_64-linux-gnu/libglib-2.0.so.0
Sep  7 21:09:59 osmo-gsm-tester-rnd ofonod[8561]: #10 0x7f0d9fa93d82 in /lib/x86_64-linux-gnu/libglib-2.0.so.0
Sep  7 21:09:59 osmo-gsm-tester-rnd ofonod[8561]: #11 0x564f6bc9914d in /root/ofono/src/ofonod
Sep  7 21:09:59 osmo-gsm-tester-rnd ofonod[8561]: #12 0x7f0d9eeb62b1 in /lib/x86_64-linux-gnu/libc.so.6
Sep  7 21:09:59 osmo-gsm-tester-rnd systemd[1]: ofono.service: Main process exited, code=exited, status=1/FAILURE
Sep  7 21:09:59 osmo-gsm-tester-rnd ofonod[8561]: +++++++++++++++++++++++++++
Sep  7 21:09:59 osmo-gsm-tester-rnd systemd[1]: ofono.service: Unit entered failed state.
Sep  7 21:09:59 osmo-gsm-tester-rnd systemd[1]: ofono.service: Failed with result 'exit-code'.
Sep  7 21:10:00 osmo-gsm-tester-rnd kernel: [1512058.693767] device eth1 left promiscuous mode
Sep  7 21:10:01 osmo-gsm-tester-rnd CRON[8990]: (root) CMD (if [ -x /etc/munin/plugins/apt_all ]; then /etc/munin/plugins/apt_all update 7200 12 >/dev/null; elif [ -x /etc/munin/plugins/apt ]; then /etc/munin/plu
gins/apt update 7200 12 >/dev/null; fi)
Sep  7 21:10:02 osmo-gsm-tester-rnd systemd[1]: ofono.service: Service hold-off time over, scheduling restart.
Sep  7 21:10:02 osmo-gsm-tester-rnd systemd[1]: Stopped Telephony service.

#5 Updated by neels 12 days ago

re-added the -d, but left QMI debugging off... out of gut feel only.

#6 Updated by neels 12 days ago

ran only the sysmocell5000 test, ofono didn't crash (test failed for another reason): https://jenkins.osmocom.org/jenkins/job/osmo-gsm-tester_manual-run-all/81/

ran only the suites leading up to the crash (-s ​aoip_sms:trx-b200 ​-s ​sms:trx-sysmocell5000), ofono crashed: https://jenkins.osmocom.org/jenkins/job/osmo-gsm-tester_manual-run-all/82/console

ran only trx-b200 followed by not 5000, but standard sysmobts (-s ​aoip_sms:trx-b200 ​-s ​sms:sysmo), ofono didn't crash: https://jenkins.osmocom.org/jenkins/job/osmo-gsm-tester_manual-run-all/84

It seems to be only the combination of trx-b200 followed by trx-sysmocell5000 that triggers the failure.
Maybe because the sysmocell5000 takes a lot shorter than the sysmobts to start up and ofono gets queried again very rapidly??

#7 Updated by lynxis 12 days ago

hi neels,

I've tried to get a coredump from ofono, but it seems some signal handler is preventing it (glib?). How do I have to call the osmo-gsm-tester to provoke the crash?

#8 Updated by lynxis 12 days ago

I managed to reproduce the crash. The problem lies in a race condition within the network-register service.

The calls within network-register should walk this way:

qmi_netreg_probe() /* try to register indications against the modem */
||
\/
create_nas_cb()
||
\/
set_event_cb()
||
\/
ofono_netreg_register(qmimodem)
||
\/
ss_info_notify() /* callback when the modem send an indication */
||
\/
ofono_netreg_status_notify(netreg, status, lac, cellid, tech);

But...
the qmimodem might call ofono_netreg_status_notify() before ofono_netreg_register(qmimodem).

#9 Updated by lynxis 12 days ago

  • Status changed from New to In Progress
  • Priority changed from Urgent to High
  • % Done changed from 0 to 90

working patch in lynxis/master.
missing: send patches upstream.

#10 Updated by neels 12 days ago

lynxis wrote:

But...
the qmimodem might call ofono_netreg_status_notify() before ofono_netreg_register(qmimodem).

sounds almost like a bug pespin told me about, that a modem may say that it is registered even before it is registered, causing some tests to get odd results.
(i.e. not crashing, but even though the encryption key should mismatch, the modem says it is registered before it has even contacted the BTS.)
Can this be related? If yes, pespin would probably like to hear about it.

working patch in lynxis/master.

yay! \o/

installed where? on prod as well as RnD?
(then again it appears to not hit on the prod setup)

Indeed I see no ofono crashes anymore on the RnD, only other failures now.

#11 Updated by pespin 11 days ago

Hi, good news you found a fix.

Indeed, it could be related to this one https://osmocom.org/issues/2456, or to this one https://osmocom.org/issues/2458. Lynxis, What do you think? Please inform us here once you have merge it to osmo-gsm-tester and we are running it in both prod and rnd, so we can check that the issues doesn't appear anymore.

#12 Updated by pespin 9 days ago

Hi, I think we got the same crash in prod, visible in job #2817. lynxis can you confirm it's the same? looks like it is. This time ofono was build with "-g" and we have nice backtraces.

Sep 10 21:10:46.461701 testbed-production ofonod[31591]: plugins/gobi.c:gobi_post_sim() 0x177cf00
Sep 10 21:10:46.461746 testbed-production ofonod[31591]: drivers/qmimodem/radio-settings.c:qmi_radio_settings_probe()
Sep 10 21:10:46.461812 testbed-production ofonod[31591]: drivers/qmimodem/sms.c:qmi_sms_probe()
Sep 10 21:10:46.461850 testbed-production ofonod[31591]: src/modem.c:get_modem_property() modem 0x177cf00 property AlwaysOnline
Sep 10 21:10:46.461875 testbed-production ofonod[31591]: src/modem.c:modem_change_state() old state: 2, new state: 3
Sep 10 21:10:46.461898 testbed-production ofonod[31591]: plugins/gobi.c:gobi_post_online() 0x177cf00
Sep 10 21:10:46.461925 testbed-production ofonod[31591]: drivers/qmimodem/network-registration.c:qmi_netreg_probe()
Sep 10 21:10:46.461963 testbed-production ofonod[31591]: drivers/qmimodem/ussd.c:qmi_ussd_probe()
Sep 10 21:10:46.461998 testbed-production ofonod[31591]: drivers/qmimodem/gprs.c:qmi_gprs_probe()
Sep 10 21:10:46.462043 testbed-production ofonod[31591]: drivers/qmimodem/gprs-context.c:qmi_gprs_context_probe()
Sep 10 21:10:46.462362 testbed-production ofonod[31591]: drivers/qmimodem/sim.c:qmi_read_attributes() file id 0x6f40 path len 0
Sep 10 21:10:46.491907 testbed-production ofonod[31591]: drivers/qmimodem/radio-settings.c:create_nas_cb()
Sep 10 21:10:46.492520 testbed-production ofonod[31591]: src/radio-settings.c:radio_load_settings() TechnologyPreference: 0
Sep 10 21:10:46.492546 testbed-production ofonod[31591]: src/radio-settings.c:radio_load_settings() GsmBand: 0
Sep 10 21:10:46.492568 testbed-production ofonod[31591]: src/radio-settings.c:radio_load_settings() UmtsBand: 0
Sep 10 21:10:46.523658 testbed-production ofonod[31591]: drivers/qmimodem/sms.c:create_wms_cb()
Sep 10 21:10:46.555792 testbed-production ofonod[31591]: drivers/qmimodem/network-registration.c:create_nas_cb()
Sep 10 21:10:46.587910 testbed-production ofonod[31591]: drivers/qmimodem/ussd.c:create_voice_cb()
Sep 10 21:10:46.619539 testbed-production ofonod[31591]: drivers/qmimodem/gprs.c:create_nas_cb()
Sep 10 21:10:46.651757 testbed-production ofonod[31591]: drivers/qmimodem/gprs-context.c:create_wda_cb()
Sep 10 21:10:46.683899 testbed-production ofonod[31591]: drivers/qmimodem/sim.c:get_file_attributes_cb()
Sep 10 21:10:46.684069 testbed-production ofonod[31591]: drivers/qmimodem/sim.c:qmi_read_record() file id 0x6f40 path len 0
Sep 10 21:10:46.716155 testbed-production ofonod[31591]: drivers/qmimodem/sms.c:set_event_cb()
Sep 10 21:10:46.779502 testbed-production ofonod[31591]: drivers/qmimodem/network-registration.c:ss_info_notify()
Sep 10 21:10:46.779578 testbed-production ofonod[31591]: drivers/qmimodem/network-registration.c:extract_ss_info()
Sep 10 21:10:46.779603 testbed-production ofonod[31591]: drivers/qmimodem/network-registration.c:extract_ss_info() serving system status 2
Sep 10 21:10:46.779626 testbed-production ofonod[31591]: drivers/qmimodem/network-registration.c:extract_ss_info() radio in use 0
Sep 10 21:10:46.779652 testbed-production ofonod[31591]: drivers/qmimodem/network-registration.c:extract_ss_info() lac -1 cellid -1 tech -1
Sep 10 21:10:46.779678 testbed-production ofonod[31591]: src/network.c:ofono_netreg_status_notify() /sierra_3 status 2 tech -1 lac -1 ci -1
Sep 10 21:10:46.780265 testbed-production ofonod[31591]: src/network.c:current_operator_callback() 0x179e7b0, (nil)
Sep 10 21:10:46.780330 testbed-production ofonod[31591]: Aborting (signal 11) [/usr/local/sbin/ofonod]
Sep 10 21:10:46.782035 testbed-production ofonod[31591]: ++++++++ backtrace ++++++++
Sep 10 21:10:46.801161 testbed-production ofonod[31591]: #0  0x7f4037d0f0e0 in /lib/x86_64-linux-gnu/libc.so.6
Sep 10 21:10:46.815797 testbed-production ofonod[31591]: #1  0x4d39d9 in notify_status_watches() at oot/src/ofono/src/network.c:1194
Sep 10 21:10:46.816260 testbed-production ofonod[31591]: #2  0x4d40d2 in ofono_netreg_status_notify() at oot/src/ofono/src/network.c:1397
Sep 10 21:10:46.817415 testbed-production ofonod[31591]: #3  0x457f9b in ss_info_notify() at oot/src/ofono/drivers/qmimodem/network-registration.c:174
Sep 10 21:10:46.820191 testbed-production ofonod[31591]: #4  0x452b2f in service_notify() at oot/src/ofono/drivers/qmimodem/qmi.c:704
Sep 10 21:10:46.820810 testbed-production ofonod[31591]: #5  0x452c11 in handle_indication() at oot/src/ofono/drivers/qmimodem/qmi.c:743
Sep 10 21:10:46.821006 testbed-production ofonod[31591]: #6  0x452db6 in handle_packet() at oot/src/ofono/drivers/qmimodem/qmi.c:803
Sep 10 21:10:46.821197 testbed-production ofonod[31591]: #7  0x452fb8 in received_data() at oot/src/ofono/drivers/qmimodem/qmi.c:867
Sep 10 21:10:46.821330 testbed-production ofonod[31591]: #8  0x7f403851ab6d in /lib/x86_64-linux-gnu/libglib-2.0.so.0
Sep 10 21:10:46.821450 testbed-production ofonod[31591]: #9  0x7f403851af48 in /lib/x86_64-linux-gnu/libglib-2.0.so.0
Sep 10 21:10:46.821566 testbed-production ofonod[31591]: #10 0x7f403851b272 in /lib/x86_64-linux-gnu/libglib-2.0.so.0
Sep 10 21:10:46.828743 testbed-production systemd[1]: ofono.service: main process exited, code=exited, status=1/FAILURE

#13 Updated by lynxis 9 days ago

looks like the same.

#14 Updated by lynxis 8 days ago

The patch got accepted upstream. Need only to merge the lynxis/master into osmo-gsm-tester

#15 Updated by lynxis 7 days ago

  • Status changed from In Progress to Resolved
  • % Done changed from 90 to 100

Also available in: Atom PDF