Project

General

Profile

log

pespin, 06/16/2017 01:39 PM

 
1

    
2
--------------------------------------------------------------------------------------------
3
trial
4
--------------------------------------------------------------------------------------------
5
15:30:29.796939 tst                            trial: Detailed log at /var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/log  [trial.py:83]
6
15:30:30.064320 cnf                    ResourcesPool: DBG: Found config file resources.conf as /opt/pespin/osmo-gsm-tester/example/resources.conf in /opt/pespin/osmo-gsm-tester/example which is /opt/pespin/osmo-gsm-tester/example  [config.py:98]
7
15:30:30.068401 cnf                    ResourcesPool: DBG: Found path state_dir as /var/tmp/osmo-gsm-tester/state  [config.py:140]
8

    
9
---------------------------------------------------------------------
10
trial ussd
11
---------------------------------------------------------------------
12
15:30:30.235674 tst                             ussd: reserving resources in /var/tmp/osmo-gsm-tester/state ...  [trial↪ussd]  [suite.py:225]
13
15:30:30.239829 tst                             ussd: DBG: {combining='resources'}  [trial↪ussd]  [suite.py:199]
14
15:30:30.244189 tst {combining_scenarios='resources'}: DBG: {definition_conf={bts=[{'times': '1'}], ip_address=[{'times': '1'}], modem=[{'times': '1'}]}}  [trial↪ussd↪{combining_scenarios='resources'}]  [suite.py:202]
15
15:30:30.261979 tst                             ussd: Reserving 1 x bts (candidates: 2)  [trial↪ussd]  [resource.py:306]
16
15:30:30.282761 tst                             ussd: DBG: Picked - _hash: 36c23d509008ecd040d6e5df7c2c3d2f78b76d4f
17
  addr: 10.42.42.114
18
  band: GSM-1800
19
  ipa_unit_id: '1'
20
  label: sysmoBTS 1002
21
  type: osmo-bts-sysmo
22
  [trial↪ussd]  [resource.py:350]
23
15:30:30.286543 tst                             ussd: Reserving 1 x ip_address (candidates: 5)  [trial↪ussd]  [resource.py:306]
24
15:30:30.298466 tst                             ussd: DBG: Picked - _hash: fd103b22c7cf2480d609150e06f4bbd92ac78d8c
25
  addr: 10.42.42.2
26
  [trial↪ussd]  [resource.py:350]
27
15:30:30.302251 tst                             ussd: Reserving 1 x modem (candidates: 4)  [trial↪ussd]  [resource.py:306]
28
15:30:30.320329 tst                             ussd: DBG: Picked - _hash: 9e5ee90e41c66221458631199aa772afa7957a26
29
  imsi: '901700000009031'
30
  ki: 80A37E6FDEA931EAC92FFA5F671EFEAD
31
  label: sierra_1
32
  path: /sierra_1
33
  [trial↪ussd]  [resource.py:350]
34

    
35
----------------------------------------------
36
trial ussd assert_extension.py
37
----------------------------------------------
38
15:30:30.420664 ---                ReservedResources: DBG: requesting use of ip_address {specifics={}}  [resource.py:469]
39
15:30:30.452902 tst                             ussd: Using 1 x ip_address (candidates: 1)  [trial↪ussd]  [resource.py:306]
40
15:30:30.495624 tst                             ussd: DBG: Picked - _hash: fd103b22c7cf2480d609150e06f4bbd92ac78d8c
41
  _reserved_by: ussd-15134-1497619830
42
  addr: 10.42.42.2
43
  [trial↪ussd]  [resource.py:350]
44
15:30:30.527584 ---                ReservedResources: DBG: {available=1}  [resource.py:475]
45
15:30:30.559429 ---                ReservedResources: DBG: {using={_hash='fd103b22c7cf2480d609150e06f4bbd92ac78d8c', _reserved_by='ussd-15134-1497619830', addr='10.42.42.2'}}  [resource.py:493]
46
15:30:30.591663 ---                ReservedResources: DBG: requesting use of bts {specifics={}}  [resource.py:469]
47
15:30:30.623783 tst                             ussd: Using 1 x bts (candidates: 1)  [trial↪ussd]  [resource.py:306]
48
15:30:30.674434 tst                             ussd: DBG: Picked - _hash: 36c23d509008ecd040d6e5df7c2c3d2f78b76d4f
49
  _reserved_by: ussd-15134-1497619830
50
  addr: 10.42.42.114
51
  band: GSM-1800
52
  ipa_unit_id: '1'
53
  label: sysmoBTS 1002
54
  type: osmo-bts-sysmo
55
  [trial↪ussd]  [resource.py:350]
56
15:30:30.706037 ---                ReservedResources: DBG: {available=1}  [resource.py:475]
57
15:30:30.737893 ---                ReservedResources: DBG: {using={_hash='36c23d509008ecd040d6e5df7c2c3d2f78b76d4f', _reserved_by='ussd-15134-1497619830', addr='10.42.42.114', band='GSM-1800', ipa_unit_id='1', label='sysmoBTS 1002', type='osmo-bts-sysmo'}}  [resource.py:493]
58
15:30:30.769873 tst                             ussd: DBG: create BTS object {type='osmo-bts-sysmo'}  [trial↪ussd]  [suite.py:425]
59
15:30:30.802223 ---                ReservedResources: DBG: requesting use of modem {specifics={}}  [resource.py:469]
60
15:30:30.834776 tst                             ussd: Using 1 x modem (candidates: 1)  [trial↪ussd]  [resource.py:306]
61
15:30:30.883947 tst                             ussd: DBG: Picked - _hash: 9e5ee90e41c66221458631199aa772afa7957a26
62
  _reserved_by: ussd-15134-1497619830
63
  imsi: '901700000009031'
64
  ki: 80A37E6FDEA931EAC92FFA5F671EFEAD
65
  label: sierra_1
66
  path: /sierra_1
67
  [trial↪ussd]  [resource.py:350]
68
15:30:30.916325 ---                ReservedResources: DBG: {available=1}  [resource.py:475]
69
15:30:30.948395 ---                ReservedResources: DBG: {using={_hash='9e5ee90e41c66221458631199aa772afa7957a26', _reserved_by='ussd-15134-1497619830', imsi='901700000009031', ki='80A37E6FDEA931EAC92FFA5F671EFEAD', label='sierra_1', path='/sierra_1'}}  [resource.py:493]
70
15:30:30.980409 tst                             ussd: DBG: create Modem object {conf={_hash='9e5ee90e41c66221458631199aa772afa7957a26', _reserved_by='ussd-15134-1497619830', _used=True, imsi='901700000009031', ki='80A37E6FDEA931EAC92FFA5F671EFEAD', label='sierra_1', path='/sierra_1'}}  [trial↪ussd]  [suite.py:335]
71
15:30:31.094426 tst           assert_extension.py:10: start nitb and bts...  [trial↪ussd↪assert_extension.py:10]  [assert_extension.py:10]
72
15:30:31.254228 run             osmo-nitb_10.42.42.2: Starting osmo-nitb  [trial↪ussd↪osmo-nitb_10.42.42.2]  [osmo_nitb.py:41]
73
15:30:31.287817 run             osmo-nitb_10.42.42.2: DBG: {config_file='/var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-nitb_10.42.42.2/osmo-nitb.cfg'}  [trial↪ussd↪osmo-nitb_10.42.42.2]  [osmo_nitb.py:68]
74
15:30:31.321393 cnf             osmo-nitb_10.42.42.2: DBG: Found config file defaults.conf as /opt/pespin/osmo-gsm-tester/example/defaults.conf in /opt/pespin/osmo-gsm-tester/example which is /opt/pespin/osmo-gsm-tester/example  [trial↪ussd↪osmo-nitb_10.42.42.2]  [config.py:98]
75
15:30:31.470475 tst                             ussd: DBG: {combining='config'}  [trial↪ussd]  [suite.py:199]
76
15:30:31.503075 tst   {combining_scenarios='config'}: DBG: {definition_conf={}}  [trial↪ussd↪{combining_scenarios='config'}]  [suite.py:202]
77
15:30:31.537720 cnf                   osmo-bts-sysmo: DBG: Found config file defaults.conf as /opt/pespin/osmo-gsm-tester/example/defaults.conf in /opt/pespin/osmo-gsm-tester/example which is /opt/pespin/osmo-gsm-tester/example  [trial↪ussd↪osmo-bts-sysmo]  [config.py:98]
78
15:30:31.685000 cnf                   osmo-bts-sysmo: DBG: Found config file defaults.conf as /opt/pespin/osmo-gsm-tester/example/defaults.conf in /opt/pespin/osmo-gsm-tester/example which is /opt/pespin/osmo-gsm-tester/example  [trial↪ussd↪osmo-bts-sysmo]  [config.py:98]
79
15:30:31.831754 run                   osmo-bts-sysmo: DBG: {conf={_hash='36c23d509008ecd040d6e5df7c2c3d2f78b76d4f', _reserved_by='ussd-15134-1497619830', _used=True, addr='10.42.42.114', band='GSM-1800', base_station_id_code='63', ipa_unit_id='1', label='sysmoBTS 1002', location_area_code='23', osmobsc_bts_type='sysmobts', stream_id='255', trx_list=[{'max_power_red': '0', 'arfcn': '868', 'timeslot_list': [{'phys_chan_config': 'CCCH+SDCCH4'}, {'phys_chan_config': 'SDCCH8'}, {'phys_chan_config': 'TCH/F'}, {'phys_chan_config': 'TCH/F'}, {'phys_chan_config': 'TCH/F'}, {'phys_chan_config': 'TCH/F'}, {'phys_chan_config': 'TCH/F'}, {'phys_chan_config': 'TCH/F'}]}], type='osmo-bts-sysmo'}}  [trial↪ussd↪osmo-bts-sysmo]  [bts_sysmo.py:136]
80
15:30:31.883972 run             osmo-nitb_10.42.42.2: DBG: NITB CONFIG:
81
{'nitb': {'ip_address': {'_hash': 'fd103b22c7cf2480d609150e06f4bbd92ac78d8c',
82
                         '_reserved_by': 'ussd-15134-1497619830',
83
                         '_used': True,
84
                         'addr': '10.42.42.2'},
85
          'net': {'auth_policy': 'closed',
86
                  'bts_list': [{'_hash': '36c23d509008ecd040d6e5df7c2c3d2f78b76d4f',
87
                                '_reserved_by': 'ussd-15134-1497619830',
88
                                '_used': True,
89
                                'addr': '10.42.42.114',
90
                                'band': 'GSM-1800',
91
                                'base_station_id_code': '63',
92
                                'ipa_unit_id': '1',
93
                                'label': 'sysmoBTS 1002',
94
                                'location_area_code': '23',
95
                                'osmobsc_bts_type': 'sysmobts',
96
                                'stream_id': '255',
97
                                'trx_list': [{'arfcn': '868',
98
                                              'max_power_red': '0',
99
                                              'timeslot_list': [{'phys_chan_config': 'CCCH+SDCCH4'},
100
                                                                {'phys_chan_config': 'SDCCH8'},
101
                                                                {'phys_chan_config': 'TCH/F'},
102
                                                                {'phys_chan_config': 'TCH/F'},
103
                                                                {'phys_chan_config': 'TCH/F'},
104
                                                                {'phys_chan_config': 'TCH/F'},
105
                                                                {'phys_chan_config': 'TCH/F'},
106
                                                                {'phys_chan_config': 'TCH/F'}]}],
107
                                'type': 'osmo-bts-sysmo'}],
108
                  'encryption': 'a5 0',
109
                  'long_name': 'osmo-gsm-tester-nitb',
110
                  'mcc': '901',
111
                  'mnc': '70',
112
                  'short_name': 'osmo-gsm-tester-nitb'}}}  [trial↪ussd↪osmo-nitb_10.42.42.2]  [osmo_nitb.py:80]
113
15:30:31.982739 cnf                        Templates: DBG: rendering osmo-nitb.cfg.tmpl  [trial↪ussd↪osmo-nitb_10.42.42.2↪Templates]  [template.py:53]
114
15:30:32.017693 run             osmo-nitb_10.42.42.2: DBG: ! Configuration rendered by osmo-gsm-tester
115
password foo
116
!
117
log stderr
118
 logging filter all 1
119
 logging color 1
120
 logging print category 1
121
 logging print extended-timestamp 1
122
 logging level all debug
123
!
124
line vty
125
 no login
126
 bind 10.42.42.2
127
!
128
e1_input
129
 e1_line 0 driver ipa
130
 ipa bind 10.42.42.2
131
network
132
 network country code 901
133
 mobile network code 70
134
 short name osmo-gsm-tester-nitb
135
 long name osmo-gsm-tester-nitb
136
 auth policy closed
137
 location updating reject cause 13
138
 encryption a5 0
139
 neci 1
140
 rrlp mode none
141
 mm info 1
142
 handover 0
143
 handover window rxlev averaging 10
144
 handover window rxqual averaging 1
145
 handover window rxlev neighbor averaging 10
146
 handover power budget interval 6
147
 handover power budget hysteresis 3
148
 handover maximum distance 9999
149
 timer t3101 10
150
 timer t3103 0
151
 timer t3105 0
152
 timer t3107 0
153
 timer t3109 4
154
 timer t3111 0
155
 timer t3113 60
156
 timer t3115 0
157
 timer t3117 0
158
 timer t3119 0
159
 timer t3141 0
160
 bts 0
161
  type sysmobts
162
  band GSM-1800
163
  cell_identity 0
164
  location_area_code 23
165
  training_sequence_code 7
166
  base_station_id_code 63
167
  ms max power 33
168
  cell reselection hysteresis 4
169
  rxlev access min 0
170
  channel allocator ascending
171
  rach tx integer 9
172
  rach max transmission 7
173
  ip.access unit_id 1 0
174
  oml ip.access stream_id 255 line 0
175
  gprs mode none
176
  trx 0
177
   rf_locked 0
178
   arfcn 868
179
   nominal power 23
180
   max_power_red 0
181
   rsl e1 tei 0
182
   timeslot 0
183
    phys_chan_config CCCH+SDCCH4
184
   timeslot 1
185
    phys_chan_config SDCCH8
186
   timeslot 2
187
    phys_chan_config TCH/F
188
   timeslot 3
189
    phys_chan_config TCH/F
190
   timeslot 4
191
    phys_chan_config TCH/F
192
   timeslot 5
193
    phys_chan_config TCH/F
194
   timeslot 6
195
    phys_chan_config TCH/F
196
   timeslot 7
197
    phys_chan_config TCH/F
198
smpp
199
 local-tcp-ip 10.42.42.2 2775
200
 system-id test
201
 policy closed
202
 esme test
203
  password test
204
  default-route
205
ctrl
206
 bind 10.42.42.2
207
  [trial↪ussd↪osmo-nitb_10.42.42.2]  [osmo_nitb.py:84]
208
15:30:32.050616 tst                            trial: DBG: {bin_name='osmo-nitb', matches=['osmo-nitb.build-65.tgz']}  [trial.py:146]
209
15:30:32.201418 run pcap-recorder_eth1(filters='host 10.42.42.2 and port not 22'): Recording pcap /var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-nitb_10.42.42.2/pcap host 10.42.42.2 and port not 22  [trial↪ussd↪osmo-nitb_10.42.42.2↪pcap-recorder_eth1(filters='host 10.42.42.2 and port not 22')]  [pcap_recorder.py:40]
210
15:30:32.233965 run pcap-recorder_eth1(filters='host 10.42.42.2 and port not 22'): DBG: cd '/var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-nitb_10.42.42.2/pcap';  tcpdump -n -i eth1 -w /var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-nitb_10.42.42.2/pcap/pcap-recorder_eth1(filters='host 10.42.42.2 and port not 22').pcap host 10.42.42.2 and port not 22  [trial↪ussd↪osmo-nitb_10.42.42.2↪pcap-recorder_eth1(filters='host 10.42.42.2 and port not 22')↪pcap-recorder_eth1(filters='host 10.42.42.2 and port not 22')]  [process.py:67]
211
15:30:32.267794 run pcap-recorder_eth1(filters='host 10.42.42.2 and port not 22'): DBG: /var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-nitb_10.42.42.2/pcap/stdout  [trial↪ussd↪osmo-nitb_10.42.42.2↪pcap-recorder_eth1(filters='host 10.42.42.2 and port not 22')↪pcap-recorder_eth1(filters='host 10.42.42.2 and port not 22')]  [process.py:57]
212
15:30:32.300383 run pcap-recorder_eth1(filters='host 10.42.42.2 and port not 22'): DBG: /var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-nitb_10.42.42.2/pcap/stderr  [trial↪ussd↪osmo-nitb_10.42.42.2↪pcap-recorder_eth1(filters='host 10.42.42.2 and port not 22')↪pcap-recorder_eth1(filters='host 10.42.42.2 and port not 22')]  [process.py:57]
213
15:30:32.342080 run pcap-recorder_eth1(filters='host 10.42.42.2 and port not 22')(pid=15148): Launched  [trial↪ussd↪osmo-nitb_10.42.42.2↪pcap-recorder_eth1(filters='host 10.42.42.2 and port not 22')↪pcap-recorder_eth1(filters='host 10.42.42.2 and port not 22')(pid=15148)]  [process.py:78]
214
15:30:32.374245 run             osmo-nitb_10.42.42.2: DBG: {binary='/var/tmp/osmo-gsm-tester/trials/trial/inst/osmo-nitb/bin/osmo-nitb', env={LD_LIBRARY_PATH='/var/tmp/osmo-gsm-tester/trials/trial/inst/osmo-nitb/lib'}, run_dir=/var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-nitb_10.42.42.2}  [trial↪ussd↪osmo-nitb_10.42.42.2]  [osmo_nitb.py:58]
215
15:30:32.405175 run             osmo-nitb_10.42.42.2: DBG: cd '/var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-nitb_10.42.42.2'; LD_LIBRARY_PATH='/var/tmp/osmo-gsm-tester/trials/trial/inst/osmo-nitb/lib' /var/tmp/osmo-gsm-tester/trials/trial/inst/osmo-nitb/bin/osmo-nitb -c /var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-nitb_10.42.42.2/osmo-nitb.cfg  [trial↪ussd↪osmo-nitb_10.42.42.2↪osmo-nitb_10.42.42.2]  [process.py:67]
216
15:30:32.436389 run             osmo-nitb_10.42.42.2: DBG: /var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-nitb_10.42.42.2/stdout  [trial↪ussd↪osmo-nitb_10.42.42.2↪osmo-nitb_10.42.42.2]  [process.py:57]
217
15:30:32.467548 run             osmo-nitb_10.42.42.2: DBG: /var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-nitb_10.42.42.2/stderr  [trial↪ussd↪osmo-nitb_10.42.42.2↪osmo-nitb_10.42.42.2]  [process.py:57]
218
15:30:32.511370 run  osmo-nitb_10.42.42.2(pid=15149): Launched  [trial↪ussd↪osmo-nitb_10.42.42.2↪osmo-nitb_10.42.42.2(pid=15149)]  [process.py:78]
219
15:30:32.544020 run                   osmo-bts-sysmo: Starting sysmoBTS to connect to osmo-nitb_10.42.42.2  [trial↪ussd↪osmo-bts-sysmo]  [bts_sysmo.py:47]
220
15:30:32.577779 run                   osmo-bts-sysmo: DBG: {config_file='/var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-bts-sysmo/osmo-bts-sysmo.cfg'}  [trial↪ussd↪osmo-bts-sysmo]  [bts_sysmo.py:118]
221
15:30:32.611821 cnf                   osmo-bts-sysmo: DBG: Found config file defaults.conf as /opt/pespin/osmo-gsm-tester/example/defaults.conf in /opt/pespin/osmo-gsm-tester/example which is /opt/pespin/osmo-gsm-tester/example  [trial↪ussd↪osmo-bts-sysmo]  [config.py:98]
222
15:30:32.763716 run                   osmo-bts-sysmo: DBG: SYSMOBTS CONFIG:
223
{'osmo_bts_sysmo': {'_hash': '36c23d509008ecd040d6e5df7c2c3d2f78b76d4f',
224
                    '_reserved_by': 'ussd-15134-1497619830',
225
                    '_used': True,
226
                    'addr': '10.42.42.114',
227
                    'band': 'GSM-1800',
228
                    'ipa_unit_id': '1',
229
                    'label': 'sysmoBTS 1002',
230
                    'oml_remote_ip': '10.42.42.2',
231
                    'type': 'osmo-bts-sysmo'}}  [trial↪ussd↪osmo-bts-sysmo]  [bts_sysmo.py:125]
232
15:30:32.805703 cnf                        Templates: DBG: rendering osmo-bts-sysmo.cfg.tmpl  [trial↪ussd↪osmo-nitb_10.42.42.2↪Templates]  [template.py:53]
233
15:30:32.838725 run                   osmo-bts-sysmo: DBG: ! Configuration rendered by osmo-gsm-tester
234
log stderr
235
  logging color 1
236
  logging print extended-timestamp 1
237
  logging print category 1
238
  logging level abis debug
239
  logging level oml debug
240
  logging level pag debug
241
  logging level rll debug
242
  logging level rr debug
243
  logging level rsl debug
244
!
245
phy 0
246
 instance 0
247
bts 0
248
 band GSM-1800
249
 ipa unit-id 1 0
250
 oml remote-ip 10.42.42.2
251
 gsmtap-sapi bcch
252
 gsmtap-sapi ccch
253
 gsmtap-sapi rach
254
 gsmtap-sapi agch
255
 gsmtap-sapi pch
256
 gsmtap-sapi sdcch
257
 gsmtap-sapi tch/f
258
 gsmtap-sapi tch/h
259
 gsmtap-sapi pacch
260
 gsmtap-sapi pdtch
261
 gsmtap-sapi ptcch
262
 gsmtap-sapi cbch
263
 gsmtap-sapi sacch
264
 trx 0
265
  phy 0 instance 0
266
  [trial↪ussd↪osmo-bts-sysmo]  [bts_sysmo.py:129]
267
15:30:32.871695 tst                            trial: DBG: {bin_name='osmo-bts-sysmo', matches=['osmo-bts-sysmo.build-96.tgz']}  [trial.py:146]
268
15:30:32.905625 run                    rm-remote-dir: DBG: ['ssh', 'root@10.42.42.114', 'test ! -d /osmo-gsm-tester || rm -rf /osmo-gsm-tester'] {conf={}, dir=/var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-bts-sysmo/rm-remote-dir}  [trial↪ussd↪osmo-bts-sysmo↪rm-remote-dir]  [process.py:227]
269
15:30:32.938076 run                    rm-remote-dir: DBG: cd '/var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-bts-sysmo/rm-remote-dir';  ssh root@10.42.42.114 test ! -d /osmo-gsm-tester || rm -rf /osmo-gsm-tester  [trial↪ussd↪osmo-bts-sysmo↪rm-remote-dir]  [process.py:67]
270
15:30:32.971152 run                    rm-remote-dir: DBG: /var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-bts-sysmo/rm-remote-dir/stdout  [trial↪ussd↪osmo-bts-sysmo↪rm-remote-dir]  [process.py:57]
271
15:30:33.004728 run                    rm-remote-dir: DBG: /var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-bts-sysmo/rm-remote-dir/stderr  [trial↪ussd↪osmo-bts-sysmo↪rm-remote-dir]  [process.py:57]
272
15:30:33.049294 run         rm-remote-dir(pid=15150): Launched  [trial↪ussd↪osmo-bts-sysmo↪rm-remote-dir(pid=15150)]  [process.py:78]
273
15:30:37.092389 run         rm-remote-dir(pid=15150): DBG: Cleanup  [trial↪ussd↪osmo-bts-sysmo↪rm-remote-dir(pid=15150)]  [process.py:150]
274
15:30:37.123753 run         rm-remote-dir(pid=15150): Terminated: ok {rc=0}  [trial↪ussd↪osmo-bts-sysmo↪rm-remote-dir(pid=15150)]  [process.py:129]
275
15:30:37.156981 run                    mk-remote-dir: DBG: ['ssh', 'root@10.42.42.114', 'mkdir -p /osmo-gsm-tester'] {conf={}, dir=/var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-bts-sysmo/mk-remote-dir}  [trial↪ussd↪osmo-bts-sysmo↪mk-remote-dir]  [process.py:227]
276
15:30:37.187907 run                    mk-remote-dir: DBG: cd '/var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-bts-sysmo/mk-remote-dir';  ssh root@10.42.42.114 mkdir -p /osmo-gsm-tester  [trial↪ussd↪osmo-bts-sysmo↪mk-remote-dir]  [process.py:67]
277
15:30:37.219595 run                    mk-remote-dir: DBG: /var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-bts-sysmo/mk-remote-dir/stdout  [trial↪ussd↪osmo-bts-sysmo↪mk-remote-dir]  [process.py:57]
278
15:30:37.251350 run                    mk-remote-dir: DBG: /var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-bts-sysmo/mk-remote-dir/stderr  [trial↪ussd↪osmo-bts-sysmo↪mk-remote-dir]  [process.py:57]
279
15:30:37.294879 run         mk-remote-dir(pid=15151): Launched  [trial↪ussd↪osmo-bts-sysmo↪mk-remote-dir(pid=15151)]  [process.py:78]
280
15:30:39.333865 run         mk-remote-dir(pid=15151): DBG: Cleanup  [trial↪ussd↪osmo-bts-sysmo↪mk-remote-dir(pid=15151)]  [process.py:150]
281
15:30:39.367871 run         mk-remote-dir(pid=15151): Terminated: ok {rc=0}  [trial↪ussd↪osmo-bts-sysmo↪mk-remote-dir(pid=15151)]  [process.py:129]
282
15:30:39.402526 run             scp-inst-to-sysmobts: DBG: cd '/var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-bts-sysmo/scp-inst-to-sysmobts';  scp -r /var/tmp/osmo-gsm-tester/trials/trial/inst/osmo-bts-sysmo root@10.42.42.114:/osmo-gsm-tester/osmo-bts-sysmo  [trial↪ussd↪osmo-bts-sysmo↪scp-inst-to-sysmobts]  [process.py:67]
283
15:30:39.436156 run             scp-inst-to-sysmobts: DBG: /var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-bts-sysmo/scp-inst-to-sysmobts/stdout  [trial↪ussd↪osmo-bts-sysmo↪scp-inst-to-sysmobts]  [process.py:57]
284
15:30:39.469802 run             scp-inst-to-sysmobts: DBG: /var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-bts-sysmo/scp-inst-to-sysmobts/stderr  [trial↪ussd↪osmo-bts-sysmo↪scp-inst-to-sysmobts]  [process.py:57]
285
15:30:39.511486 run  scp-inst-to-sysmobts(pid=15152): Launched  [trial↪ussd↪osmo-bts-sysmo↪scp-inst-to-sysmobts(pid=15152)]  [process.py:78]
286
15:31:09.590133 run  scp-inst-to-sysmobts(pid=15152): DBG: Cleanup  [trial↪ussd↪osmo-bts-sysmo↪scp-inst-to-sysmobts(pid=15152)]  [process.py:150]
287
15:31:09.622290 run  scp-inst-to-sysmobts(pid=15152): Terminated: ok {rc=0}  [trial↪ussd↪osmo-bts-sysmo↪scp-inst-to-sysmobts(pid=15152)]  [process.py:129]
288
15:31:09.655876 run                mk-remote-run-dir: DBG: ['ssh', 'root@10.42.42.114', 'mkdir -p /osmo-gsm-tester/osmo-bts-sysmo'] {conf={}, dir=/var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-bts-sysmo/mk-remote-run-dir}  [trial↪ussd↪osmo-bts-sysmo↪mk-remote-run-dir]  [process.py:227]
289
15:31:09.687491 run                mk-remote-run-dir: DBG: cd '/var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-bts-sysmo/mk-remote-run-dir';  ssh root@10.42.42.114 mkdir -p /osmo-gsm-tester/osmo-bts-sysmo  [trial↪ussd↪osmo-bts-sysmo↪mk-remote-run-dir]  [process.py:67]
290
15:31:09.719976 run                mk-remote-run-dir: DBG: /var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-bts-sysmo/mk-remote-run-dir/stdout  [trial↪ussd↪osmo-bts-sysmo↪mk-remote-run-dir]  [process.py:57]
291
15:31:09.752591 run                mk-remote-run-dir: DBG: /var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-bts-sysmo/mk-remote-run-dir/stderr  [trial↪ussd↪osmo-bts-sysmo↪mk-remote-run-dir]  [process.py:57]
292
15:31:09.796539 run     mk-remote-run-dir(pid=15165): Launched  [trial↪ussd↪osmo-bts-sysmo↪mk-remote-run-dir(pid=15165)]  [process.py:78]
293
15:31:13.839279 run     mk-remote-run-dir(pid=15165): DBG: Cleanup  [trial↪ussd↪osmo-bts-sysmo↪mk-remote-run-dir(pid=15165)]  [process.py:150]
294
15:31:13.872437 run     mk-remote-run-dir(pid=15165): Terminated: ok {rc=0}  [trial↪ussd↪osmo-bts-sysmo↪mk-remote-run-dir(pid=15165)]  [process.py:129]
295
15:31:13.906564 run              scp-cfg-to-sysmobts: DBG: cd '/var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-bts-sysmo/scp-cfg-to-sysmobts';  scp -r /var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-bts-sysmo/osmo-bts-sysmo.cfg root@10.42.42.114:/osmo-gsm-tester/osmo-bts-sysmo.cfg  [trial↪ussd↪osmo-bts-sysmo↪scp-cfg-to-sysmobts]  [process.py:67]
296
15:31:13.940200 run              scp-cfg-to-sysmobts: DBG: /var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-bts-sysmo/scp-cfg-to-sysmobts/stdout  [trial↪ussd↪osmo-bts-sysmo↪scp-cfg-to-sysmobts]  [process.py:57]
297
15:31:13.973165 run              scp-cfg-to-sysmobts: DBG: /var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-bts-sysmo/scp-cfg-to-sysmobts/stderr  [trial↪ussd↪osmo-bts-sysmo↪scp-cfg-to-sysmobts]  [process.py:57]
298
15:31:14.016009 run   scp-cfg-to-sysmobts(pid=15166): Launched  [trial↪ussd↪osmo-bts-sysmo↪scp-cfg-to-sysmobts(pid=15166)]  [process.py:78]
299
15:31:19.058174 run   scp-cfg-to-sysmobts(pid=15166): DBG: Cleanup  [trial↪ussd↪osmo-bts-sysmo↪scp-cfg-to-sysmobts(pid=15166)]  [process.py:150]
300
15:31:19.089576 run   scp-cfg-to-sysmobts(pid=15166): Terminated: ok {rc=0}  [trial↪ussd↪osmo-bts-sysmo↪scp-cfg-to-sysmobts(pid=15166)]  [process.py:129]
301
15:31:19.122276 run              reload-dsp-firmware: DBG: ['ssh', 'root@10.42.42.114', '/bin/sh -c "cat /lib/firmware/sysmobts-v?.bit > /dev/fpgadl_par0 ; cat /lib/firmware/sysmobts-v?.out > /dev/dspdl_dm644x_0"'] {conf={}, dir=/var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-bts-sysmo/reload-dsp-firmware}  [trial↪ussd↪osmo-bts-sysmo↪reload-dsp-firmware]  [process.py:227]
302
15:31:19.153740 run              reload-dsp-firmware: DBG: cd '/var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-bts-sysmo/reload-dsp-firmware';  ssh root@10.42.42.114 /bin/sh -c "cat /lib/firmware/sysmobts-v?.bit > /dev/fpgadl_par0 ; cat /lib/firmware/sysmobts-v?.out > /dev/dspdl_dm644x_0"  [trial↪ussd↪osmo-bts-sysmo↪reload-dsp-firmware]  [process.py:67]
303
15:31:19.185298 run              reload-dsp-firmware: DBG: /var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-bts-sysmo/reload-dsp-firmware/stdout  [trial↪ussd↪osmo-bts-sysmo↪reload-dsp-firmware]  [process.py:57]
304
15:31:19.216348 run              reload-dsp-firmware: DBG: /var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-bts-sysmo/reload-dsp-firmware/stderr  [trial↪ussd↪osmo-bts-sysmo↪reload-dsp-firmware]  [process.py:57]
305
15:31:19.261611 run   reload-dsp-firmware(pid=15169): Launched  [trial↪ussd↪osmo-bts-sysmo↪reload-dsp-firmware(pid=15169)]  [process.py:78]
306
15:31:22.305083 run   reload-dsp-firmware(pid=15169): DBG: Cleanup  [trial↪ussd↪osmo-bts-sysmo↪reload-dsp-firmware(pid=15169)]  [process.py:150]
307
15:31:22.338796 run   reload-dsp-firmware(pid=15169): Terminated: ok {rc=0}  [trial↪ussd↪osmo-bts-sysmo↪reload-dsp-firmware(pid=15169)]  [process.py:129]
308
15:31:22.373372 run                   osmo-bts-sysmo: DBG: ['ssh', 'root@10.42.42.114', 'cd "/osmo-gsm-tester/osmo-bts-sysmo"; LD_LIBRARY_PATH=/osmo-gsm-tester/osmo-bts-sysmo/lib /osmo-gsm-tester/osmo-bts-sysmo/bin/osmo-bts-sysmo -c /osmo-gsm-tester/osmo-bts-sysmo.cfg -r 1 -i 10.42.42.2'] {conf={}, dir=/var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-bts-sysmo/osmo-bts-sysmo}  [trial↪ussd↪osmo-bts-sysmo↪osmo-bts-sysmo]  [process.py:227]
309
15:31:22.406401 run                   osmo-bts-sysmo: DBG: cd '/var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-bts-sysmo/osmo-bts-sysmo';  ssh root@10.42.42.114 cd "/osmo-gsm-tester/osmo-bts-sysmo"; LD_LIBRARY_PATH=/osmo-gsm-tester/osmo-bts-sysmo/lib /osmo-gsm-tester/osmo-bts-sysmo/bin/osmo-bts-sysmo -c /osmo-gsm-tester/osmo-bts-sysmo.cfg -r 1 -i 10.42.42.2  [trial↪ussd↪osmo-bts-sysmo↪osmo-bts-sysmo]  [process.py:67]
310
15:31:22.440114 run                   osmo-bts-sysmo: DBG: /var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-bts-sysmo/osmo-bts-sysmo/stdout  [trial↪ussd↪osmo-bts-sysmo↪osmo-bts-sysmo]  [process.py:57]
311
15:31:22.473722 run                   osmo-bts-sysmo: DBG: /var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/osmo-bts-sysmo/osmo-bts-sysmo/stderr  [trial↪ussd↪osmo-bts-sysmo↪osmo-bts-sysmo]  [process.py:57]
312
15:31:22.518326 run        osmo-bts-sysmo(pid=15170): Launched  [trial↪ussd↪osmo-bts-sysmo↪osmo-bts-sysmo(pid=15170)]  [process.py:78]
313
15:31:22.568142 run             osmo-nitb_10.42.42.2: Add subscriber {imsi='901700000009031', msisdn='5275'}  [trial↪ussd↪osmo-nitb_10.42.42.2]  [osmo_nitb.py:107]
314
15:31:22.600287 bus Ctrl(host='10.42.42.2', port=4249): DBG: Connecting  [trial↪ussd↪osmo-nitb_10.42.42.2↪CTRL(10.42.42.2:4249)↪Ctrl(host='10.42.42.2', port=4249)]  [osmo_ctrl.py:54]
315
15:31:22.641448 bus Ctrl(host='10.42.42.2', port=4249): DBG: Sending {data='SET 0 subscriber-modify-v1 901700000009031,5275,comp128v1,80A37E6FDEA931EAC92FFA5F671EFEAD'}  [trial↪ussd↪osmo-nitb_10.42.42.2↪CTRL(10.42.42.2:4249)↪Ctrl(host='10.42.42.2', port=4249)]  [osmo_ctrl.py:65]
316
15:31:22.762461 bus            CTRL(10.42.42.2:4249): DBG: Created subscriber {imsi='901700000009031', msisdn='5275'}  [trial↪ussd↪osmo-nitb_10.42.42.2↪CTRL(10.42.42.2:4249)]  [osmo_nitb.py:156]
317
15:31:22.793526 bus Ctrl(host='10.42.42.2', port=4249): DBG: Disconnecting  [trial↪ussd↪osmo-nitb_10.42.42.2↪CTRL(10.42.42.2:4249)↪Ctrl(host='10.42.42.2', port=4249)]  [osmo_ctrl.py:60]
318
15:31:22.832108 bus                        /sierra_1: DBG: Powered == False  [trial↪ussd↪/sierra_1↪/sierra_1]  [ofono_client.py:290]
319
15:31:22.862395 tst                        /sierra_1: DBG: Powering on  [trial↪ussd↪/sierra_1]  [ofono_client.py:490]
320
15:31:22.893719 bus                        /sierra_1: Setting Powered True  [trial↪ussd↪/sierra_1↪/sierra_1]  [ofono_client.py:298]
321
15:31:23.139839 bus                        /sierra_1: DBG: Powered == True  [trial↪ussd↪/sierra_1↪/sierra_1]  [ofono_client.py:290]
322
15:31:23.177546 bus                        /sierra_1: DBG: interface enabled: org.ofono.VoiceCallManager  [trial↪ussd↪/sierra_1↪/sierra_1]  [ofono_client.py:230]
323
15:31:23.213254 bus                        /sierra_1: Setting Online True  [trial↪ussd↪/sierra_1↪/sierra_1]  [ofono_client.py:298]
324
15:31:23.427322 bus                        /sierra_1: DBG: interface enabled: org.ofono.LocationReporting  [trial↪ussd↪/sierra_1↪/sierra_1]  [ofono_client.py:230]
325
15:31:23.482953 bus                        /sierra_1: DBG: Online == True  [trial↪ussd↪/sierra_1↪/sierra_1]  [ofono_client.py:290]
326
15:31:23.521481 bus                        /sierra_1: DBG: interface enabled: org.ofono.SimManager  [trial↪ussd↪/sierra_1↪/sierra_1]  [ofono_client.py:230]
327
15:31:23.568435 bus                        /sierra_1: DBG: has_interface(org.ofono.NetworkRegistration, org.ofono.MessageManager) == False  [trial↪ussd↪/sierra_1↪/sierra_1]  [ofono_client.py:282]
328
15:31:24.616123 bus                        /sierra_1: DBG: interface enabled: org.ofono.AllowedAccessPoints  [trial↪ussd↪/sierra_1↪/sierra_1]  [ofono_client.py:230]
329
15:31:24.652764 bus                        /sierra_1: DBG: interface enabled: org.ofono.RadioSettings  [trial↪ussd↪/sierra_1↪/sierra_1]  [ofono_client.py:230]
330
15:31:24.689849 bus                        /sierra_1: DBG: interface enabled: org.ofono.SupplementaryServices  [trial↪ussd↪/sierra_1↪/sierra_1]  [ofono_client.py:230]
331
15:31:24.729384 bus                        /sierra_1: DBG: interface enabled: org.ofono.ConnectionManager  [trial↪ussd↪/sierra_1↪/sierra_1]  [ofono_client.py:230]
332
15:31:24.766605 bus                        /sierra_1: DBG: interface enabled: org.ofono.NetworkRegistration  [trial↪ussd↪/sierra_1↪/sierra_1]  [ofono_client.py:230]
333
15:31:24.802540 bus                        /sierra_1: DBG: Connecting 1 signals for org.ofono.NetworkRegistration  [trial↪ussd↪/sierra_1↪/sierra_1]  [ofono_client.py:270]
334
15:31:24.859657 bus                        /sierra_1: DBG: has_interface(org.ofono.NetworkRegistration, org.ofono.MessageManager) == False  [trial↪ussd↪/sierra_1↪/sierra_1]  [ofono_client.py:282]
335
15:31:25.899579 bus                        /sierra_1: DBG: interface enabled: org.ofono.MessageManager, org.ofono.PushNotification, org.ofono.SmartMessaging  [trial↪ussd↪/sierra_1↪/sierra_1]  [ofono_client.py:230]
336
15:31:25.934114 bus                        /sierra_1: DBG: Connecting 1 signals for org.ofono.MessageManager  [trial↪ussd↪/sierra_1↪/sierra_1]  [ofono_client.py:270]
337
15:31:25.997189 bus                        /sierra_1: DBG: has_interface(org.ofono.NetworkRegistration, org.ofono.MessageManager) == True  [trial↪ussd↪/sierra_1↪/sierra_1]  [ofono_client.py:282]
338
15:31:26.034325 tst                        /sierra_1: DBG: status: denied  [trial↪ussd↪/sierra_1]  [ofono_client.py:407]
339
15:31:26.066069 tst                        /sierra_1: Connect to ('901', '70')  [trial↪ussd↪/sierra_1]  [ofono_client.py:504]
340
15:31:26.098403 tst                        /sierra_1: DBG: Scanning for operators...  [trial↪ussd↪/sierra_1]  [ofono_client.py:423]
341
15:31:26.140338 tst                        /sierra_1: Manufacturer: 'Sierra Wireless, Incorporated', Model: 'MC7304', Revision: 'SWI9X15C_05.05.66.00 r29972 CARMD-EV-FRMWR1 2015/10/08 08:36:28'  [trial↪ussd↪/sierra_1]  [ofono_client.py:543]
342
15:31:26.237915 tst           assert_extension.py:20: waiting for modems to attach...  [trial↪ussd↪assert_extension.py:20]  [assert_extension.py:20]
343
15:31:26.407873 tst                        /sierra_1: DBG: status: denied  [trial↪ussd↪/sierra_1]  [ofono_client.py:407]
344
15:31:27.449255 tst                        /sierra_1: DBG: status: denied  [trial↪ussd↪/sierra_1]  [ofono_client.py:407]
345
15:31:28.491055 tst                        /sierra_1: DBG: status: denied  [trial↪ussd↪/sierra_1]  [ofono_client.py:407]
346
15:31:29.531777 tst                        /sierra_1: DBG: status: denied  [trial↪ussd↪/sierra_1]  [ofono_client.py:407]
347
15:31:30.572292 tst                        /sierra_1: DBG: status: denied  [trial↪ussd↪/sierra_1]  [ofono_client.py:407]
348
15:31:31.613479 tst                        /sierra_1: DBG: status: denied  [trial↪ussd↪/sierra_1]  [ofono_client.py:407]
349
15:31:32.655864 tst                        /sierra_1: DBG: status: denied  [trial↪ussd↪/sierra_1]  [ofono_client.py:407]
350
15:31:33.697884 tst                        /sierra_1: DBG: status: denied  [trial↪ussd↪/sierra_1]  [ofono_client.py:407]
351
15:31:34.737927 tst                        /sierra_1: DBG: status: denied  [trial↪ussd↪/sierra_1]  [ofono_client.py:407]
352
15:31:35.778802 tst                        /sierra_1: DBG: status: denied  [trial↪ussd↪/sierra_1]  [ofono_client.py:407]
353
15:31:36.818645 tst                        /sierra_1: DBG: status: denied  [trial↪ussd↪/sierra_1]  [ofono_client.py:407]
354
15:31:37.857213 tst                        /sierra_1: DBG: status: denied  [trial↪ussd↪/sierra_1]  [ofono_client.py:407]
355
15:31:38.899319 tst                        /sierra_1: DBG: status: denied  [trial↪ussd↪/sierra_1]  [ofono_client.py:407]
356
15:31:39.940771 tst                        /sierra_1: DBG: status: denied  [trial↪ussd↪/sierra_1]  [ofono_client.py:407]
357
15:31:40.984231 tst                        /sierra_1: DBG: scanned operators:  [('/sierra_1/operator/26201', {'MobileNetworkCode': '01', 'Name': 'TDG', 'Status': 'forbidden', 'Technologies': ['gsm', 'umts', 'lte'], 'MobileCountryCode': '262'}), ('/sierra_1/operator/26203', {'MobileNetworkCode': '03', 'Name': 'E-Plus', 'Status': 'forbidden', 'Technologies': ['gsm', 'umts', 'lte'], 'MobileCountryCode': '262'}), ('/sierra_1/operator/26202', {'MobileNetworkCode': '02', 'Name': 'Vodafone', 'Status': 'forbidden', 'Technologies': ['gsm', 'umts'], 'MobileCountryCode': '262'})]  [trial↪ussd↪/sierra_1]  [ofono_client.py:460]
358
15:31:41.018053 tst                        /sierra_1: DBG: Failed to find Network Operator {attempts=1, mcc_mnc=('901', '70')}  [trial↪ussd↪/sierra_1]  [ofono_client.py:475]
359
15:31:41.051814 tst                        /sierra_1: DBG: Scanning for operators...  [trial↪ussd↪/sierra_1]  [ofono_client.py:423]
360
15:31:41.089576 tst                        /sierra_1: DBG: status: denied  [trial↪ussd↪/sierra_1]  [ofono_client.py:407]
361
15:31:42.129628 tst                        /sierra_1: DBG: status: denied  [trial↪ussd↪/sierra_1]  [ofono_client.py:407]
362
15:31:43.170666 tst                        /sierra_1: DBG: status: denied  [trial↪ussd↪/sierra_1]  [ofono_client.py:407]
363
15:31:44.212056 tst                        /sierra_1: DBG: status: denied  [trial↪ussd↪/sierra_1]  [ofono_client.py:407]
364
15:31:45.254034 tst                        /sierra_1: DBG: status: denied  [trial↪ussd↪/sierra_1]  [ofono_client.py:407]
365
15:31:46.293962 tst                        /sierra_1: DBG: status: denied  [trial↪ussd↪/sierra_1]  [ofono_client.py:407]
366
15:31:47.334619 tst                        /sierra_1: DBG: status: denied  [trial↪ussd↪/sierra_1]  [ofono_client.py:407]
367
15:31:48.376031 tst                        /sierra_1: DBG: status: denied  [trial↪ussd↪/sierra_1]  [ofono_client.py:407]
368
15:31:49.417929 tst                        /sierra_1: DBG: status: denied  [trial↪ussd↪/sierra_1]  [ofono_client.py:407]
369
15:31:50.460965 tst                        /sierra_1: DBG: scanned operators:  [('/sierra_1/operator/90170', {'MobileNetworkCode': '70', 'Name': '901-70', 'Status': 'available', 'Technologies': ['gsm'], 'MobileCountryCode': '901'}), ('/sierra_1/operator/26203', {'MobileNetworkCode': '03', 'Name': 'E-Plus', 'Status': 'forbidden', 'Technologies': ['gsm', 'umts', 'lte'], 'MobileCountryCode': '262'}), ('/sierra_1/operator/26201', {'MobileNetworkCode': '01', 'Name': 'TDG', 'Status': 'forbidden', 'Technologies': ['gsm', 'umts', 'lte'], 'MobileCountryCode': '262'}), ('/sierra_1/operator/26202', {'MobileNetworkCode': '02', 'Name': 'Vodafone', 'Status': 'forbidden', 'Technologies': ['lte'], 'MobileCountryCode': '262'})]  [trial↪ussd↪/sierra_1]  [ofono_client.py:460]
370
15:31:50.499767 tst                        /sierra_1: Registering with operator /sierra_1/operator/90170 ('901', '70')  [trial↪ussd↪/sierra_1]  [ofono_client.py:479]
371
15:31:50.590487 tst                        /sierra_1: DBG: status: denied  [trial↪ussd↪/sierra_1]  [ofono_client.py:407]
372
15:31:51.631127 tst                        /sierra_1: DBG: status: denied  [trial↪ussd↪/sierra_1]  [ofono_client.py:407]
373
15:31:52.672625 tst                        /sierra_1: DBG: status: denied  [trial↪ussd↪/sierra_1]  [ofono_client.py:407]
374
15:31:53.715979 tst                        /sierra_1: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Status=unregistered  [trial↪ussd↪/sierra_1]  [ofono_client.py:401]
375
15:31:53.752092 tst                        /sierra_1: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Technology=gsm  [trial↪ussd↪/sierra_1]  [ofono_client.py:401]
376
15:31:53.786723 tst                        /sierra_1: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Status=registered  [trial↪ussd↪/sierra_1]  [ofono_client.py:401]
377
15:31:53.820286 tst                        /sierra_1: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> LocationAreaCode=23  [trial↪ussd↪/sierra_1]  [ofono_client.py:401]
378
15:31:53.853715 tst                        /sierra_1: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> CellId=0  [trial↪ussd↪/sierra_1]  [ofono_client.py:401]
379
15:31:53.890552 tst                        /sierra_1: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Name=osmo-gsm-tester-nitb  [trial↪ussd↪/sierra_1]  [ofono_client.py:401]
380
15:31:53.927841 tst                        /sierra_1: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> MobileCountryCode=901  [trial↪ussd↪/sierra_1]  [ofono_client.py:401]
381
15:31:53.963767 tst                        /sierra_1: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> MobileNetworkCode=70  [trial↪ussd↪/sierra_1]  [ofono_client.py:401]
382
15:31:53.997027 tst                        /sierra_1: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Name=901-70  [trial↪ussd↪/sierra_1]  [ofono_client.py:401]
383
15:31:54.030090 tst                        /sierra_1: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Strength=40  [trial↪ussd↪/sierra_1]  [ofono_client.py:401]
384
15:31:54.068501 tst                        /sierra_1: DBG: status: registered  [trial↪ussd↪/sierra_1]  [ofono_client.py:407]
385
15:31:54.102937 bus Ctrl(host='10.42.42.2', port=4249): DBG: Connecting  [trial↪ussd↪osmo-nitb_10.42.42.2↪CTRL(10.42.42.2:4249)↪Ctrl(host='10.42.42.2', port=4249)]  [osmo_ctrl.py:54]
386
15:31:54.137332 bus Ctrl(host='10.42.42.2', port=4249): DBG: Sending {data='GET 0 subscriber-list-active-v1'}  [trial↪ussd↪osmo-nitb_10.42.42.2↪CTRL(10.42.42.2:4249)↪Ctrl(host='10.42.42.2', port=4249)]  [osmo_ctrl.py:65]
387
15:31:54.177475 bus Ctrl(host='10.42.42.2', port=4249): DBG: Disconnecting  [trial↪ussd↪osmo-nitb_10.42.42.2↪CTRL(10.42.42.2:4249)↪Ctrl(host='10.42.42.2', port=4249)]  [osmo_ctrl.py:60]
388
15:31:54.210505 run             osmo-nitb_10.42.42.2: DBG: attached: GET_REPLY 0 subscriber-list-active-v1 901700000009031,5275   [trial↪ussd↪osmo-nitb_10.42.42.2]  [osmo_nitb.py:115]
389
15:31:54.307400 tst           assert_extension.py:29: send ussd  [trial↪ussd↪assert_extension.py:29]  [assert_extension.py:29]
390
15:31:54.587191 tst           assert_extension.py:30: failed: GLib.Error('GDBus.Error:org.ofono.Error.Terminated: Operation was terminated by the network', 'g-io-error-quark', 36)  [trial↪ussd↪assert_extension.py:30]  [assert_extension.py:35]
391
15:31:54.687214 tst           assert_extension.py:29: send ussd  [trial↪ussd↪assert_extension.py:29]  [assert_extension.py:29]
392
15:31:54.971284 tst           assert_extension.py:30: failed: GLib.Error('GDBus.Error:org.ofono.Error.Terminated: Operation was terminated by the network', 'g-io-error-quark', 36)  [trial↪ussd↪assert_extension.py:30]  [assert_extension.py:35]
393
15:31:55.078418 tst           assert_extension.py:29: send ussd  [trial↪ussd↪assert_extension.py:29]  [assert_extension.py:29]
394
15:31:55.483701 tst           assert_extension.py:30: failed: GLib.Error('GDBus.Error:org.ofono.Error.Terminated: Operation was terminated by the network', 'g-io-error-quark', 36)  [trial↪ussd↪assert_extension.py:30]  [assert_extension.py:35]
395
15:31:55.584122 tst           assert_extension.py:29: send ussd  [trial↪ussd↪assert_extension.py:29]  [assert_extension.py:29]
396
15:31:55.867032 tst           assert_extension.py:30: failed: GLib.Error('GDBus.Error:org.ofono.Error.Terminated: Operation was terminated by the network', 'g-io-error-quark', 36)  [trial↪ussd↪assert_extension.py:30]  [assert_extension.py:35]
397
15:31:55.967723 tst           assert_extension.py:29: send ussd  [trial↪ussd↪assert_extension.py:29]  [assert_extension.py:29]
398
15:31:58.401366 tst           assert_extension.py:31: success!  [trial↪ussd↪assert_extension.py:31]  [assert_extension.py:31]
399
15:31:58.635159 tst           assert_extension.py:29: send ussd  [trial↪ussd↪assert_extension.py:29]  [assert_extension.py:29]
400
15:31:59.612255 tst           assert_extension.py:30: failed: GLib.Error('GDBus.Error:org.ofono.Error.Terminated: Operation was terminated by the network', 'g-io-error-quark', 36)  [trial↪ussd↪assert_extension.py:30]  [assert_extension.py:35]
401
15:31:59.712239 tst           assert_extension.py:29: send ussd  [trial↪ussd↪assert_extension.py:29]  [assert_extension.py:29]
402
15:31:59.994775 tst           assert_extension.py:30: failed: GLib.Error('GDBus.Error:org.ofono.Error.Terminated: Operation was terminated by the network', 'g-io-error-quark', 36)  [trial↪ussd↪assert_extension.py:30]  [assert_extension.py:35]
403
15:32:00.091946 tst           assert_extension.py:29: send ussd  [trial↪ussd↪assert_extension.py:29]  [assert_extension.py:29]
404
15:32:02.171763 tst           assert_extension.py:31: success!  [trial↪ussd↪assert_extension.py:31]  [assert_extension.py:31]
405
15:32:02.398277 tst           assert_extension.py:29: send ussd  [trial↪ussd↪assert_extension.py:29]  [assert_extension.py:29]
406
15:32:04.991311 tst           assert_extension.py:31: success!  [trial↪ussd↪assert_extension.py:31]  [assert_extension.py:31]
407
15:32:05.219297 tst           assert_extension.py:29: send ussd  [trial↪ussd↪assert_extension.py:29]  [assert_extension.py:29]
408
15:32:05.885039 tst           assert_extension.py:30: failed: GLib.Error('GDBus.Error:org.ofono.Error.Terminated: Operation was terminated by the network', 'g-io-error-quark', 36)  [trial↪ussd↪assert_extension.py:30]  [assert_extension.py:35]
409
15:32:05.989384 tst           assert_extension.py:29: send ussd  [trial↪ussd↪assert_extension.py:29]  [assert_extension.py:29]
410
15:32:06.297841 tst           assert_extension.py:30: failed: GLib.Error('GDBus.Error:org.ofono.Error.Terminated: Operation was terminated by the network', 'g-io-error-quark', 36)  [trial↪ussd↪assert_extension.py:30]  [assert_extension.py:35]
411
15:32:06.395094 tst           assert_extension.py:29: send ussd  [trial↪ussd↪assert_extension.py:29]  [assert_extension.py:29]
412
15:32:08.511366 tst           assert_extension.py:31: success!  [trial↪ussd↪assert_extension.py:31]  [assert_extension.py:31]
413
15:32:08.744482 tst           assert_extension.py:29: send ussd  [trial↪ussd↪assert_extension.py:29]  [assert_extension.py:29]
414
15:32:11.582764 tst           assert_extension.py:31: success!  [trial↪ussd↪assert_extension.py:31]  [assert_extension.py:31]
415
15:32:11.816790 tst           assert_extension.py:29: send ussd  [trial↪ussd↪assert_extension.py:29]  [assert_extension.py:29]
416
15:32:12.475359 tst           assert_extension.py:30: failed: GLib.Error('GDBus.Error:org.ofono.Error.Terminated: Operation was terminated by the network', 'g-io-error-quark', 36)  [trial↪ussd↪assert_extension.py:30]  [assert_extension.py:35]
417
15:32:12.578607 tst           assert_extension.py:29: send ussd  [trial↪ussd↪assert_extension.py:29]  [assert_extension.py:29]
418
15:32:12.891939 tst           assert_extension.py:30: failed: GLib.Error('GDBus.Error:org.ofono.Error.Terminated: Operation was terminated by the network', 'g-io-error-quark', 36)  [trial↪ussd↪assert_extension.py:30]  [assert_extension.py:35]
419
15:32:12.994606 tst           assert_extension.py:29: send ussd  [trial↪ussd↪assert_extension.py:29]  [assert_extension.py:29]
420
15:32:15.101787 tst           assert_extension.py:31: success!  [trial↪ussd↪assert_extension.py:31]  [assert_extension.py:31]
421
15:32:15.327471 tst           assert_extension.py:29: send ussd  [trial↪ussd↪assert_extension.py:29]  [assert_extension.py:29]
422
15:32:18.174389 tst           assert_extension.py:31: success!  [trial↪ussd↪assert_extension.py:31]  [assert_extension.py:31]
423
15:32:18.401217 tst           assert_extension.py:29: send ussd  [trial↪ussd↪assert_extension.py:29]  [assert_extension.py:29]
424
15:32:19.066886 tst           assert_extension.py:30: failed: GLib.Error('GDBus.Error:org.ofono.Error.Terminated: Operation was terminated by the network', 'g-io-error-quark', 36)  [trial↪ussd↪assert_extension.py:30]  [assert_extension.py:35]
425
15:32:19.166728 tst           assert_extension.py:29: send ussd  [trial↪ussd↪assert_extension.py:29]  [assert_extension.py:29]
426
15:32:19.451622 tst           assert_extension.py:30: failed: GLib.Error('GDBus.Error:org.ofono.Error.Terminated: Operation was terminated by the network', 'g-io-error-quark', 36)  [trial↪ussd↪assert_extension.py:30]  [assert_extension.py:35]
427
15:32:19.548366 tst           assert_extension.py:29: send ussd  [trial↪ussd↪assert_extension.py:29]  [assert_extension.py:29]
428
15:32:21.695863 tst           assert_extension.py:31: success!  [trial↪ussd↪assert_extension.py:31]  [assert_extension.py:31]
429
15:32:21.930679 tst           assert_extension.py:29: send ussd  [trial↪ussd↪assert_extension.py:29]  [assert_extension.py:29]
430
15:32:24.537021 tst           assert_extension.py:31: success!  [trial↪ussd↪assert_extension.py:31]  [assert_extension.py:31]
431
15:32:24.756362 tst           assert_extension.py:29: send ussd  [trial↪ussd↪assert_extension.py:29]  [assert_extension.py:29]
432
15:32:25.402251 tst           assert_extension.py:30: failed: GLib.Error('GDBus.Error:org.ofono.Error.Terminated: Operation was terminated by the network', 'g-io-error-quark', 36)  [trial↪ussd↪assert_extension.py:30]  [assert_extension.py:35]
433
15:32:25.507202 tst           assert_extension.py:29: send ussd  [trial↪ussd↪assert_extension.py:29]  [assert_extension.py:29]
434
15:32:25.819283 tst           assert_extension.py:30: failed: GLib.Error('GDBus.Error:org.ofono.Error.Terminated: Operation was terminated by the network', 'g-io-error-quark', 36)  [trial↪ussd↪assert_extension.py:30]  [assert_extension.py:35]
435
15:32:25.917030 tst           assert_extension.py:29: send ussd  [trial↪ussd↪assert_extension.py:29]  [assert_extension.py:29]
436
15:32:28.062633 tst           assert_extension.py:31: success!  [trial↪ussd↪assert_extension.py:31]  [assert_extension.py:31]
437
15:32:28.210652 tst              assert_extension.py: Test passed (117.8 sec)  [trial↪ussd↪assert_extension.py]  [suite.py:147]
438
15:32:28.241165 run        osmo-bts-sysmo(pid=15170): Terminating (SIGINT)  [trial↪ussd↪osmo-bts-sysmo↪osmo-bts-sysmo(pid=15170)]  [process.py:104]
439
15:32:28.414834 run        osmo-bts-sysmo(pid=15170): DBG: Cleanup  [trial↪ussd↪osmo-bts-sysmo↪osmo-bts-sysmo(pid=15170)]  [process.py:150]
440
15:32:28.419742 run        osmo-bts-sysmo(pid=15170): Terminated {rc=130}  [trial↪ussd↪osmo-bts-sysmo↪osmo-bts-sysmo(pid=15170)]  [process.py:131]
441
15:32:28.423524 run  osmo-nitb_10.42.42.2(pid=15149): Terminating (SIGINT)  [trial↪ussd↪osmo-nitb_10.42.42.2↪osmo-nitb_10.42.42.2(pid=15149)]  [process.py:104]
442
15:32:31.834248 run  osmo-nitb_10.42.42.2(pid=15149): DBG: Cleanup  [trial↪ussd↪osmo-nitb_10.42.42.2↪osmo-nitb_10.42.42.2(pid=15149)]  [process.py:150]
443
15:32:31.839156 run  osmo-nitb_10.42.42.2(pid=15149): Terminated: ok {rc=0}  [trial↪ussd↪osmo-nitb_10.42.42.2↪osmo-nitb_10.42.42.2(pid=15149)]  [process.py:129]
444
15:32:31.842999 run pcap-recorder_eth1(filters='host 10.42.42.2 and port not 22')(pid=15148): Terminating (SIGINT)  [trial↪ussd↪osmo-nitb_10.42.42.2↪pcap-recorder_eth1(filters='host 10.42.42.2 and port not 22')↪pcap-recorder_eth1(filters='host 10.42.42.2 and port not 22')(pid=15148)]  [process.py:104]
445
15:32:32.022198 run pcap-recorder_eth1(filters='host 10.42.42.2 and port not 22')(pid=15148): DBG: Cleanup  [trial↪ussd↪osmo-nitb_10.42.42.2↪pcap-recorder_eth1(filters='host 10.42.42.2 and port not 22')↪pcap-recorder_eth1(filters='host 10.42.42.2 and port not 22')(pid=15148)]  [process.py:150]
446
15:32:32.027100 run pcap-recorder_eth1(filters='host 10.42.42.2 and port not 22')(pid=15148): Terminated: ok {rc=0}  [trial↪ussd↪osmo-nitb_10.42.42.2↪pcap-recorder_eth1(filters='host 10.42.42.2 and port not 22')↪pcap-recorder_eth1(filters='host 10.42.42.2 and port not 22')(pid=15148)]  [process.py:129]
447
15:32:32.031876 tst                        /sierra_1: DBG: cleanup  [trial↪ussd↪/sierra_1]  [ofono_client.py:338]
448
15:32:32.036930 tst                        /sierra_1: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Name=osmo-gsm-tester-nitb  [trial↪ussd↪/sierra_1]  [ofono_client.py:401]
449
15:32:32.043146 bus                        /sierra_1: DBG: Disconnecting 1 signals for org.ofono.MessageManager  [trial↪ussd↪/sierra_1↪/sierra_1]  [ofono_client.py:257]
450
15:32:32.048326 bus                        /sierra_1: DBG: Disconnecting 1 signals for org.ofono.NetworkRegistration  [trial↪ussd↪/sierra_1↪/sierra_1]  [ofono_client.py:257]
451
---------------------------------------------------------------------
452
trial ussd PASS
453
---------------------------------------------------------------------
454
15:32:32.126426 tst                            trial: Storing JUnit report in /var/tmp/osmo-gsm-tester/trials/trial/run.2017-06-16_15-30-29/trial.xml  [trial.py:207]
455

    
456
--------------------------------------------------------------------------------------------
457
trial PASS
458
--------------------------------------------------------------------------------------------
459
15:32:32.141524 tst                            trial: trial: PASS, 1 suites passed  [trial.py:212]
Add picture from clipboard (Maximum size: 48.8 MB)