Open Source Mobile Communications: Issueshttps://osmocom.org/https://osmocom.org/favicon.ico?16647414092016-07-27T10:30:30ZOpen Source Mobile Communications
Redmine OsmoGSMTester - Bug #1783 (Closed): jenkins deletes session before session completehttps://osmocom.org/issues/17832016-07-27T10:30:30Zlazlo
<p>After having support for running multiple scenarios in parallel we ran into a new issue.</p>
<p>When the test session is started and hence the N scenarios are started, as soon as the first scenario has finished a test result is generated in a test-report.txt file.</p>
<p>As a result of that, the shell script that is used by jenkins will think that the complete session has ended, it will rsync the test session directory and delete it after that from the test system.</p>
<p>One of the symptoms of that are exceptions like these, where a ongoing scenario is doing something with the test session directory but fails because it does not longer exist.</p>
<pre>
Jul 27 11:32:22 apu-roh logger: 20160727113222 INFO: "TestSession<tmp.ETuKTKWLIa-build-233>:StandardTestScenario<0x7f5ca8a68b50>" Creating report for test object
Jul 27 11:32:22 apu-roh logger: 20160727113222 INFO: "TestSession<tmp.ETuKTKWLIa-build-233>" Stopping test session process "tcpdump"
Jul 27 11:32:22 apu-roh logger: 20160727113222 INFO: "TestSession<tmp.ETuKTKWLIa-build-233>:ProcessNurse<tcpdump>" Trying to stop process "tcpdump"
Jul 27 11:32:22 apu-roh logger: 20160727113222 INFO: "TestSession<tmp.ETuKTKWLIa-build-233>:ProcessNurse<tcpdump>" Sending SIGTERM to 1195 ("tcpdump")
Jul 27 11:32:22 apu-roh logger: 20160727113222 INFO: "TestSession<tmp.ETuKTKWLIa-build-233>:ProcessNurse<tcpdump>" Wainting for process "tcpdump"
Jul 27 11:32:22 apu-roh logger: 20160727113222 INFO: "TestSession<tmp.ETuKTKWLIa-build-233>:ProcessNurse<tcpdump>" Process "tcpdump" has terminated
Jul 27 11:32:22 apu-roh logger: 20160727113222 INFO: --------------------------------------------------------------------------------
Jul 27 11:32:22 apu-roh logger: 20160727113222 INFO: SendMOSmsTestCase ok (10 seconds)
Jul 27 11:32:22 apu-roh logger: 20160727113222 INFO: SendMOSmsTestCase ok (10 seconds)
Jul 27 11:32:22 apu-roh logger: 20160727113222 INFO: SendMOSmsTestCase ok (11 seconds)
Jul 27 11:32:22 apu-roh logger: 20160727113222 INFO: StandardTestScenario ok (245 seconds)
Jul 27 11:32:22 apu-roh logger: 20160727113222 INFO: StandardTestScenario error!
Jul 27 11:32:22 apu-roh logger: 20160727113222 INFO:
Jul 27 11:32:22 apu-roh logger: 20160727113222 INFO: --------------------------------------------------------------------------------
Jul 27 11:32:24 apu-roh logger: 20160727113224 ERROR: /var/tmp/osmo-gsm-tester/tmp.ETuKTKWLIa-build-233 has no manifest file!
Jul 27 11:33:05 apu-roh logger: 20160727113305 INFO: "TestSession<tmp.ETuKTKWLIa-build-233>:StandardTestScenario<0x7f5ca8a68b50>:SendMOSmsTestCase<0x7f5ca8a68bd0>" success! took 61 seconds to deliver SMS to 7808
Jul 27 11:33:06 apu-roh logger: 20160727113306 INFO: "TestRunner" Releasing test case resources
Jul 27 11:33:06 apu-roh logger: 20160727113306 INFO: releasing Modem resource /wavecom_6
Jul 27 11:33:06 apu-roh logger: 20160727113306 INFO: "TestSession<tmp.ETuKTKWLIa-build-233>:StandardTestScenario<0x7f5ca8a68b50>:SendMOSmsTestCase<0x7f5ca8a68bd0>" released Modem /wavecom_6
Jul 27 11:33:06 apu-roh logger: 20160727113306 INFO: releasing Modem resource /wavecom_7
Jul 27 11:33:06 apu-roh logger: 20160727113306 INFO: "TestSession<tmp.ETuKTKWLIa-build-233>:StandardTestScenario<0x7f5ca8a68b50>:SendMOSmsTestCase<0x7f5ca8a68bd0>" released Modem /wavecom_7
...
zip
...
Jul 27 11:33:10 apu-roh logger: 20160727113310 INFO: "TestSession<tmp.ETuKTKWLIa-build-233>:StandardTestScenario<0x7f5ca8a68b50>" Tearing down test scenario dependencies
Jul 27 11:33:10 apu-roh logger: 20160727113310 INFO: "TestSession<tmp.ETuKTKWLIa-build-233>:StandardTestScenario<0x7f5ca8a68b50>" Tearing down NITB
Jul 27 11:33:10 apu-roh logger: 20160727113310 INFO: "TestSession<tmp.ETuKTKWLIa-build-233>:StandardTestScenario<0x7f5ca8a68b50>:NITB<0x7f5ca8a78d90>" Tearing down NITB
Jul 27 11:33:10 apu-roh logger: 20160727113310 INFO: "TestSession<tmp.ETuKTKWLIa-build-233>:StandardTestScenario<0x7f5ca8a68b50>" Tearing down BTS
Jul 27 11:33:10 apu-roh logger: 20160727113310 INFO: "TestSession<tmp.ETuKTKWLIa-build-233>:StandardTestScenario<0x7f5ca8a68b50>:NanoBTS<0x7f5ca8a78e10>" Tearing down BTS
Jul 27 11:33:10 apu-roh logger: 20160727113310 WARNING: log directory not existing yet! creating it /var/tmp/osmo-gsm-tester/tmp.ETuKTKWLIa-build-233/20160727112805-StandardTestScenario-nanoBTS1900
Jul 27 11:33:10 apu-roh logger: Traceback (most recent call last):
Jul 27 11:33:10 apu-roh logger: File "/usr/local/src/osmo-gsm-tester/manager.py", line 204, in tick
Jul 27 11:33:10 apu-roh logger: self.tr.tick()
Jul 27 11:33:10 apu-roh logger: File "/usr/local/src/osmo-gsm-tester/runner.py", line 277, in tick
Jul 27 11:33:10 apu-roh logger: self.clean_testsession(ts)
Jul 27 11:33:10 apu-roh logger: File "/usr/local/src/osmo-gsm-tester/runner.py", line 94, in clean_testsession
Jul 27 11:33:10 apu-roh logger: ts.teardown()
Jul 27 11:33:10 apu-roh logger: File "/usr/local/src/osmo-gsm-tester/session.py", line 178, in teardown
Jul 27 11:33:10 apu-roh logger: sc.teardown()
Jul 27 11:33:10 apu-roh logger: File "/usr/local/src/osmo-gsm-tester/scenario.py", line 292, in teardown
Jul 27 11:33:10 apu-roh logger: self._teardown_deps(ts)
Jul 27 11:33:10 apu-roh logger: File "/usr/local/src/osmo-gsm-tester/scenario.py", line 286, in _teardown_deps
Jul 27 11:33:10 apu-roh logger: resobj.teardown(ts)
Jul 27 11:33:10 apu-roh logger: File "/usr/local/src/osmo-gsm-tester/bts.py", line 371, in teardown
Jul 27 11:33:10 apu-roh logger: self.set_oml_ip(ts, nitb_addr)
Jul 27 11:33:10 apu-roh logger: File "/usr/local/src/osmo-gsm-tester/bts.py", line 352, in set_oml_ip
Jul 27 11:33:10 apu-roh logger: self.ipaccess_config(ts, ipacfg_set_oml_ip_args)
Jul 27 11:33:10 apu-roh logger: File "/usr/local/src/osmo-gsm-tester/bts.py", line 335, in ipaccess_config
Jul 27 11:33:10 apu-roh logger: p = subprocess.Popen(cmd, stdout=fd['stdout'], stderr=fd['stderr'], env=env)
Jul 27 11:33:10 apu-roh logger: File "/usr/lib/python2.7/subprocess.py", line 679, in __init__
Jul 27 11:33:10 apu-roh logger: errread, errwrite)
Jul 27 11:33:10 apu-roh logger: File "/usr/lib/python2.7/subprocess.py", line 1259, in _execute_child
Jul 27 11:33:10 apu-roh logger: raise child_exception
Jul 27 11:33:10 apu-roh logger: OSError: [Errno 2] No such file or directory
</pre>
<p>In order to fix that issue the following things should be done:</p>
<ul>
<li>make sure the test-result.txt (and .xml) is only generated after all scenarios of a test session have finished</li>
<li>make sure the contents of the test-result.txt (and .xml) is unique in such a way that you can tell the results various test scenarios appart (which is currently not the case)</li>
</ul> OsmoGSMTester - Feature #1773 (Closed): parallel scenario executionhttps://osmocom.org/issues/17732016-07-12T10:51:19Zlazlo
<p>By now we have three BTS models supported but we are still unable to properly execute more than one scenario at a time.</p>
<p>To make this happen the following things need to be done (see checklist).</p>
<p>[x] write NITB/BSC related files to new scenario directory<br />[x] write BTS realted files to new scenario directory<br />[ ] make sure two or more scenarios don't collide in some way by using same filesystem paths for files<br />[ ] make sure each scenario has its own NITB/BSC allocated and does not by some accident share the same instance<br />[ ] have tcpdump be configured more specifically to listen only to the peers that are part of a scenario</p> OsmoGSMTester - Bug #1767 (Closed): BTS config written twice in BSC confighttps://osmocom.org/issues/17672016-07-06T13:08:20Zlazlo
<p>I noticed that in the openbsc.cfg that is generated by the tester, the configuration for a BTS appears twice.</p> OsmoGSMTester - Feature #1754 (Rejected): collect ofono log outputhttps://osmocom.org/issues/17542016-06-16T11:14:14Zlazlo
<p>Implement support for collecting the ofono log / debug output and save it with the rest of the test session log files for review after test execution.</p> OsmoGSMTester - Bug #1743 (Closed): leaks resources (NITB and BTSes)https://osmocom.org/issues/17432016-06-03T15:08:36Zlazlo
<p>Recently I added some more error checking to free_deps() and free() in the resource_manager.py and noticed that the scenario is leaking its resources.</p>
<p>Actually free_deps() is called by the scenario but there is an error inside of free() - which is that the resource passed to free() and not be found in the internal backlog of resources in the resource manager.</p>
<p>This is only true for NITBs and BTSes, but not for modems.</p> OsmoGSMTester - Bug #1707 (Closed): leaks test sessionshttps://osmocom.org/issues/17072016-05-12T09:45:49Zlazlo
<p>When the osmo-gsm-tester has run more than one session, "events" like received SMS will be dispatched to test cases of previous test sessions.</p>
<p>This does not lead to the failure of the current session but is irritating and simply a bug.</p>
<p>An example for this situation can be seen in the log output of the tester</p>
<pre>
20160427185631 DEBUG: "TestSession<tmp.BRUwIH6e9z-build-304>:StandardTestScenario<0xf09690>:SendMOSmsTestCase<0xf09790>" on_tick called (ttl 145 seconds)
20160427185631 DEBUG: IN tick_scenario(): tests total 1 tests complete 0 test failed 0
20160427185633 DEBUG: IN tick_scenario(): steps total 1 steps complete 0
20160427185633 DEBUG: "TestSession<tmp.BRUwIH6e9z-build-304>:StandardTestScenario<0xf09690>:SendMOSmsTestCase<0xf09790>" on_tick called (ttl 143 seconds)
20160427185633 DEBUG: IN tick_scenario(): tests total 1 tests complete 0 test failed 0
20160427185634 DEBUG: Message: test message from TestSession<tmp.BRUwIH6e9z-build-304>:StandardTestScenario<0xf09690>:SendMOSmsTestCase<0xf09790> (rand_token=0.744257599003)
20160427185634 DEBUG: Path: /wavecom_3
20160427185634 DEBUG: Interface: org.ofono.MessageManager
20160427185634 DEBUG: LocalSentTime = 2016-04-27T18:56:30+0200
20160427185634 DEBUG: SentTime = 2016-04-27T16:56:30+0000
20160427185634 DEBUG: Sender = 7803
20160427185634 DEBUG: "TestSession<tmp.xHnW1CNJVu-build-302>:StandardTestScenario<0xe02910>:SendMOSmsTestCase<0xe02b90>" received message (not sure yet if it is for this test case)
20160427185634 DEBUG: Message: test message from TestSession<tmp.BRUwIH6e9z-build-304>:StandardTestScenario<0xf09690>:SendMOSmsTestCase<0xf09790> (rand_token=0.744257599003)
20160427185634 DEBUG: Path: /wavecom_3
20160427185634 DEBUG: Interface: org.ofono.MessageManager
20160427185634 DEBUG: LocalSentTime = 2016-04-27T18:56:30+0200
20160427185634 DEBUG: SentTime = 2016-04-27T16:56:30+0000
20160427185634 DEBUG: Sender = 7803
20160427185634 DEBUG: "TestSession<tmp.xHnW1CNJVu-build-302>:StandardTestScenario<0xe02910>:SendMOSmsTestCase<0xe02bd0>" received message (not sure yet if it is for this test case)
20160427185634 DEBUG: "TestSession<tmp.xHnW1CNJVu-build-302>:StandardTestScenario<0xe02910>:SendMOSmsTestCase<0xe02bd0>" message was directed at 'to_modem' (/wavecom_3)
20160427185634 DEBUG: "TestSession<tmp.xHnW1CNJVu-build-302>:StandardTestScenario<0xe02910>:SendMOSmsTestCase<0xe02bd0>" state = failure
20160427185634 INFO: "TestSession<tmp.xHnW1CNJVu-build-302>:StandardTestScenario<0xe02910>:SendMOSmsTestCase<0xe02bd0>" failure! random token mismatch (expected 0.460211981162)
20160427185634 DEBUG: Message: test message from TestSession<tmp.BRUwIH6e9z-build-304>:StandardTestScenario<0xf09690>:SendMOSmsTestCase<0xf09790> (rand_token=0.744257599003)
20160427185634 DEBUG: Path: /wavecom_3
20160427185634 DEBUG: Interface: org.ofono.MessageManager
20160427185634 DEBUG: LocalSentTime = 2016-04-27T18:56:30+0200
20160427185634 DEBUG: SentTime = 2016-04-27T16:56:30+0000
20160427185634 DEBUG: Sender = 7803
20160427185634 DEBUG: "TestSession<tmp.32HecBvzWT-build-303>:StandardTestScenario<0xe0c890>:SendMOSmsTestCase<0xe0c950>" received message (not sure yet if it is for this test case)
20160427185634 DEBUG: Message: test message from TestSession<tmp.BRUwIH6e9z-build-304>:StandardTestScenario<0xf09690>:SendMOSmsTestCase<0xf09790> (rand_token=0.744257599003)
20160427185634 DEBUG: Path: /wavecom_3
20160427185634 DEBUG: Interface: org.ofono.MessageManager
20160427185634 DEBUG: LocalSentTime = 2016-04-27T18:56:30+0200
20160427185634 DEBUG: SentTime = 2016-04-27T16:56:30+0000
20160427185634 DEBUG: Sender = 7803
20160427185634 DEBUG: "TestSession<tmp.32HecBvzWT-build-303>:StandardTestScenario<0xe0c890>:SendMOSmsTestCase<0xe0c990>" received message (not sure yet if it is for this test case)
20160427185634 DEBUG: "TestSession<tmp.32HecBvzWT-build-303>:StandardTestScenario<0xe0c890>:SendMOSmsTestCase<0xe0c990>" message was directed at 'to_modem' (/wavecom_3)
20160427185634 DEBUG: "TestSession<tmp.32HecBvzWT-build-303>:StandardTestScenario<0xe0c890>:SendMOSmsTestCase<0xe0c990>" state = failure
20160427185634 INFO: "TestSession<tmp.32HecBvzWT-build-303>:StandardTestScenario<0xe0c890>:SendMOSmsTestCase<0xe0c990>" failure! random token mismatch (expected 0.184061419514)
20160427185634 DEBUG: Message: test message from TestSession<tmp.BRUwIH6e9z-build-304>:StandardTestScenario<0xf09690>:SendMOSmsTestCase<0xf09790> (rand_token=0.744257599003)
20160427185634 DEBUG: Path: /wavecom_3
20160427185634 DEBUG: Interface: org.ofono.MessageManager
20160427185634 DEBUG: LocalSentTime = 2016-04-27T18:56:30+0200
20160427185634 DEBUG: SentTime = 2016-04-27T16:56:30+0000
20160427185634 DEBUG: Sender = 7803
20160427185634 DEBUG: "TestSession<tmp.BRUwIH6e9z-build-304>:StandardTestScenario<0xf09690>:SendMOSmsTestCase<0xf09750>" received message (not sure yet if it is for this test case)
20160427185634 DEBUG: Message: test message from TestSession<tmp.BRUwIH6e9z-build-304>:StandardTestScenario<0xf09690>:SendMOSmsTestCase<0xf09790> (rand_token=0.744257599003)
20160427185634 DEBUG: Path: /wavecom_3
20160427185634 DEBUG: Interface: org.ofono.MessageManager
20160427185634 DEBUG: LocalSentTime = 2016-04-27T18:56:30+0200
20160427185634 DEBUG: SentTime = 2016-04-27T16:56:30+0000
20160427185634 DEBUG: Sender = 7803
20160427185634 DEBUG: "TestSession<tmp.BRUwIH6e9z-build-304>:StandardTestScenario<0xf09690>:SendMOSmsTestCase<0xf09790>" received message (not sure yet if it is for this test case)
20160427185634 DEBUG: "TestSession<tmp.BRUwIH6e9z-build-304>:StandardTestScenario<0xf09690>:SendMOSmsTestCase<0xf09790>" message was directed at 'to_modem' (/wavecom_3)
20160427185634 DEBUG: "TestSession<tmp.BRUwIH6e9z-build-304>:StandardTestScenario<0xf09690>:SendMOSmsTestCase<0xf09790>" state = success
20160427185634 INFO: "TestSession<tmp.BRUwIH6e9z-build-304>:StandardTestScenario<0xf09690>:SendMOSmsTestCase<0xf09790>" success! took 37 seconds to deliver SMS to 7804
20160427185635 DEBUG: IN tick_scenario(): steps total 1 steps complete 0
</pre>
<p>Note that this jenkins build job failed not because of the tester but because the final "ssh rm -rf" failed.</p>
<pre>
+ ssh root@10.9.1.190 rm -rf /var/tmp/osmo-gsm-tester/tmp.BRUwIH6e9z-build-304
rm: cannot remove `/var/tmp/osmo-gsm-tester/tmp.BRUwIH6e9z-build-304': Directory not empty
Build step 'Execute shell' marked build as failure
[WARNINGS] Skipping publisher since build result is FAILURE
Recording test results
Archiving artifacts
Finished: FAILURE
</pre>
<p>Reproduce the bug run at least two test sessions and you will notice that an SMS that originates from a test case of the current test session will be dispatched to test cases of the previous test sessions (see TestSession<some-unique-value> in the log output) and these test cases will be marked as "failure" (which does not change the outcome of the current test session).</p>