My favorites ▼ | Sign in
Project Home Downloads Wiki Issues Code Search
New issue   Search
for
  Advanced search   Search tips   Subscriptions
Issue 203515: desktopui_UrlFetch.not-live failing due to DBUS error
5 people starred this issue and may be notified of changes. Back to list
 
Project Member Reported by thieule@chromium.org, Sep 14, 2011 
Test error:

Unhandled DBusException: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.

The following is in syslog:

2011-09-14T13:34:25.244749-07:00 localhost dbus[164]: [system] Rejected send message, 2 matched rules; type="method_return", sender=":1.0" (uid=0 pid=169 comm="/usr/sbin/wpa_supplicant -u -s -O/var/run/wpa_supp") interface="(unset)" member="(unset)" error name="(unset)" requested_reply="0" destination=":1.18" (uid=0 pid=2313 comm="flimflamd -I wlan1 -I wlan2 -I managed0 -I managed")

Artifacts, test results, etc available at:

https://sandbox.google.com/storage/?arg=chromeos-image-archive/x86-pineview-full/0.16.1038.0-a1-b364#chromeos-image-archive%2Fx86-pineview-full%2F0.16.1038.0-a1-b364
Sep 14, 2011
#1 thieule@chromium.org 
(No comment was entered for this change.)
Labels: TreeCloser
Sep 14, 2011
#2 thieule@chromium.org 
Paul, can you take a look at the dbus error involving wpa_supplicant?
Owner: pstew@chromium.org
Labels: -Area-DesktopUI Area-Network
Sep 14, 2011
#3 thieule@chromium.org 
Attaching VMTest stdio.
VMTest-stdio.txt
22.0 KB   View   Download
Sep 14, 2011
#4 pstew@chromium.org 
Still investigating but I'm pretty sure this is due to a change to desktopui_UrlFetch and not a flimflam issue persay.  Perhaps this is a timing issue between the DBus request and flimflam being restarted elsewhere in the test?
Cc: nirnimesh@chromium.org
Sep 14, 2011
#5 pstew@chromium.org 
Adding cmasone, since the failure happens within a recently changed bit of his code.   The error is actually in flim.GetCheckPortalList().  I'm doing a ToT build to see if I can replicate.
Cc: cmasone@chromium.org
Sep 14, 2011
#6 pstew@chromium.org 
The full stack-trace is:


	START	desktopui_UrlFetch.not-live	desktopui_UrlFetch.not-live	timestamp=1316032421	localtime=Sep 14 13:33:41	
		ERROR	desktopui_UrlFetch.not-live	desktopui_UrlFetch.not-live	timestamp=1316032468	localtime=Sep 14 13:34:28	Unhandled DBusException: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
  Traceback (most recent call last):
    File "/usr/local/autotest/common_lib/test.py", line 387, in _exec
      _cherry_pick_call(self.initialize, *args, **dargs)
    File "/usr/local/autotest/common_lib/test.py", line 535, in _cherry_pick_call
      return func(*p_args, **p_dargs)
    File "/usr/local/autotest/tests/desktopui_UrlFetch/desktopui_UrlFetch.py", line 18, in initialize
      super(desktopui_UrlFetch, self).initialize(creds='$default')
    File "/usr/local/autotest/cros/cros_ui_test.py", line 207, in initialize
      self.start_authserver()
    File "/usr/local/autotest/tests/desktopui_UrlFetch/desktopui_UrlFetch.py", line 40, in start_authserver
      super(desktopui_UrlFetch, self).start_authserver()
    File "/usr/local/autotest/cros/cros_ui_test.py", line 158, in start_authserver
      self.use_local_dns()
    File "/usr/local/autotest/cros/cros_ui_test.py", line 109, in use_local_dns
      self._flim.SetCheckPortalList('')
    File "/usr/local//usr/lib/flimflam/test/flimflam.py", line 374, in SetCheckPortalList
      self.manager.SetProperty("CheckPortalList", tech_list)
    File "/usr/local/lib/python2.6/site-packages/dbus/proxies.py", line 140, in __call__
      **keywords)
    File "/usr/local/lib/python2.6/site-packages/dbus/connection.py", line 622, in call_blocking
      message, timeout)
  DBusException: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
  
	END ERROR	desktopui_UrlFetch.not-live	desktopui_UrlFetch.not-live	timestamp=1316032468	localtime=Sep 14 13:34:28
Sep 14, 2011
#7 cmasone@chromium.org 
That's just a DBus call to flimflam.  Nothing special about it.
Sep 14, 2011
#8 pstew@chromium.org 
The special part about it is that the DEBUG log appears to imply that this call succeed at some time during this test (look at the timestamps).  It got as far as printing "Running 'restart flimflam'" which is after the "self._flim.SetCheckPortalList('')", which means it succeeded both in the self._flim.GetCheckPortalList() above the SetCheckPortalList as well as the GetObjectList() down below in revert_dns.

09/14 13:33:42 DEBUG|base_utils:0074| Running 'ls -tr1 /var/log/messages.*'
09/14 13:33:42 INFO |auth_serve:0074| Serving HTTPS on 0.0.0.0, port 443
09/14 13:33:42 DEBUG|     httpd:0202| http server on localhost:443
09/14 13:33:42 DEBUG|     httpd:0202| http server on localhost:80
09/14 13:33:42 INFO |miniFakeDn:0079| miniFakeDns listening on port 53
09/14 13:33:42 ERROR|  warnings:0029| /usr/local/lib/python2.6/site-packages/dbus/connection.py:242: DeprecationWarning: object.__init__() takes no parameters
09/14 13:33:42 ERROR|  warnings:0029|   super(Connection, self).__init__(*args, **kwargs)
09/14 13:34:20 DEBUG|base_utils:0074| Running 'logger "cros/login.py: Attempting StopSession..."'
09/14 13:34:20 DEBUG|base_utils:0074| Running 'ls -tr1 /var/log/messages.*'
09/14 13:34:22 DEBUG|base_utils:0074| Running 'logger "cros/login.py: StopSession complete."'
09/14 13:34:22 INFO |cros_ui_te:0425| Erasing fake owner state.
09/14 13:34:22 INFO | ownership:0064| [Errno 2] No such file or directory: '/var/lib/whitelist/owner.key'
09/14 13:34:24 DEBUG|cros_ui_te:0136| Considering eth0
09/14 13:34:24 DEBUG|cros_ui_te:0140| Clearing local DNS for eth0
09/14 13:34:24 DEBUG|base_utils:0074| Running 'restart flimflam'
09/14 13:34:25 DEBUG|base_utils:0106| [stdout] flimflam start/running, process 2313
09/14 13:34:25 DEBUG|cros_ui_te:0088| Attempting to resolve www.google.com. to 127.0.0.1
09/14 13:34:25 DEBUG|base_utils:0074| Running 'ping -c 1 -w 1 -q www.google.com.'
09/14 13:34:25 DEBUG|miniFakeDn:0086| Response: www.google.com. -> 127.0.0.1
09/14 13:34:25 DEBUG|cros_ui_te:0091| Resolve attempt for www.google.com. got 127.0.0.1
09/14 13:34:25 DEBUG|cros_ui_te:0088| Attempting to resolve www.google.com. to 127.0.0.1
09/14 13:34:25 DEBUG|base_utils:0074| Running 'ping -c 1 -w 1 -q www.google.com.'
09/14 13:34:25 DEBUG|miniFakeDn:0086| Response: www.google.com. -> 127.0.0.1
09/14 13:34:25 DEBUG|cros_ui_te:0091| Resolve attempt for www.google.com. got 127.0.0.1
09/14 13:34:25 DEBUG|cros_ui_te:0088| Attempting to resolve www.google.com. to 127.0.0.1
09/14 13:34:25 DEBUG|base_utils:0074| Running 'ping -c 1 -w 1 -q www.google.com.'
09/14 13:34:25 DEBUG|miniFakeDn:0086| Response: www.google.com. -> 127.0.0.1
09/14 13:34:25 DEBUG|cros_ui_te:0091| Resolve attempt for www.google.com. got 127.0.0.1
09/14 13:34:25 DEBUG|cros_ui_te:0088| Attempting to resolve www.google.com. to 127.0.0.1
09/14 13:34:25 DEBUG|base_utils:0074| Running 'ping -c 1 -w 1 -q www.google.com.'
09/14 13:34:26 DEBUG|cros_ui_te:0091| Resolve attempt for www.google.com. got 74.125.113.103
09/14 13:34:27 DEBUG|base_utils:0074| Running 'ls -tr1 /var/log/messages.*'
09/14 13:34:27 DEBUG|logging_ma:0561| Logging subprocess finished
09/14 13:34:27 DEBUG|logging_ma:0561| Logging subprocess finished


Tested this on a running system with ToT build as of now:



localhost ~ # cd /usr/local/lib/flimflam/test/
localhost test # python
Python 2.6.4 (r264:75706, Sep 14 2011, 14:53:40) 
[GCC 4.4.3] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> import flimflam
>>> import dbus
>>> from dbus.mainloop.glib import DBusGMainLoop
>>> bus_loop = DBusGMainLoop(set_as_default=True)
>>> system_bus = dbus.SystemBus(mainloop=bus_loop)
/usr/local/lib/python2.6/site-packages/dbus/connection.py:242: DeprecationWarning: object.__init__() takes no parameters
  super(Connection, self).__init__(*args, **kwargs)
>>> flim = flimflam.FlimFlam(system_bus)
>>> portal_list = flim.GetCheckPortalList()
>>> print repr(portal_list)
dbus.UTF8String('ethernet,wifi,wimax,bluetooth,cellular', variant_level=1)
>>> flim.SetCheckPortalList('')
>>> print flim.GetCheckPortalList()

>>> flim.SetCheckPortalList(portal_list)
>>> print flim.GetCheckPortalList()
ethernet,wifi,wimax,bluetooth,cellular
>>> 

I don't think this is a flimflam problem.
Owner: nirnimesh@chromium.org
Sep 14, 2011
#9 cmasone@chromium.org 
Paul, the stack trace from this test failure indicates that the failure occurred while calling  self._flim.SetCheckPortalList(''), during use_local_dns().  This happens when the test is starting up.

The code you cite runs during test cleanup, which happens no matter whether a test succeeds or fails.
Sep 14, 2011
#10 pstew@chromium.org 
Let me clarify the beginning of Comment #6 "the DEBUG log appears to imply that this call succeed at some time during this test" -- meaning that DBus calls to flimflam seem to succeed both before and after the excepted one to "self._flim.SetCheckPortalList('')".
Sep 14, 2011
#11 pstew@chromium.org 
(No comment was entered for this change.)
Cc: pstew@chromium.org
Sep 20, 2011
#12 cmasone@chromium.org 
 Issue 20238  has been merged into this issue.
Cc: r...@chromium.org i...@chromium.org ellyjo...@chromium.org benc...@chromium.org
Sep 20, 2011
#13 cmasone@chromium.org 
(No comment was entered for this change.)
Status: Assigned
Owner: cmasone@chromium.org
Labels: -Area-Network Area-Test Mstone-R16
Sep 20, 2011
#14 mtennant@chromium.org 
Saw this show up just now:

http://chromegw/i/chromiumos/builders/x86%20generic%20PFQ/builds/938/steps/VMTest/logs/stdio
Sep 24, 2011
#15 petermayo@chromium.org 
/builders/x86%20pineview%20full/builds/439/steps/VMTest/logs/stdio


17:58:42 INFO | 	START	desktopui_UrlFetch.not-live	desktopui_UrlFetch.not-live	timestamp=1316912323	localtime=Sep 24 17:58:43	
17:58:42 INFO | Bundling /build/x86-pineview/usr/local/autotest/client/site_tests/desktopui_UrlFetch into test-desktopui_UrlFetch.tar.bz2
17:59:36 INFO | 		ERROR	desktopui_UrlFetch.not-live	desktopui_UrlFetch.not-live	timestamp=1316912376	localtime=Sep 24 17:59:36	Unhandled DBusException: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
17:59:36 INFO | 	END ERROR	desktopui_UrlFetch.not-live	desktopui_UrlFetch.not-live	timestamp=1316912376	localtime=Sep 24 17:59:36	


And another one.

FYI, looks like the cleanup code was a little peevish too, but I think this is related to 19005, and non-fatal:

========== ERROR FILE /tmp/cbuildbotgRUhjk/test_harness/SimpleTestVerify/1_verify/suite_Smoke/desktopui_UrlFetch.not-live/debug/desktopui_UrlFetch.not-live.ERROR FOR TEST suite_Smoke/desktopui_UrlFetch.not-live ==============
09/24 17:58:44 ERROR|  warnings:0029| /usr/local/lib/python2.6/site-packages/dbus/connection.py:242: DeprecationWarning: object.__init__() takes no parameters
09/24 17:58:44 ERROR|  warnings:0029|   super(Connection, self).__init__(*args, **kwargs)
09/24 17:59:36 ERROR|base_utils:0106| [stderr] iptables: No chain/target/match by that name.
09/24 17:59:36 ERROR|      test:0430| Ignoring exception during cleanup() phase:
09/24 17:59:36 ERROR| traceback:0013| Traceback (most recent call last):
09/24 17:59:36 ERROR| traceback:0013|   File "/usr/local/autotest/common_lib/test.py", line 428, in _exec
09/24 17:59:36 ERROR| traceback:0013|     _cherry_pick_call(self.cleanup, *args, **dargs)
09/24 17:59:36 ERROR| traceback:0013|   File "/usr/local/autotest/common_lib/test.py", line 535, in _cherry_pick_call
09/24 17:59:36 ERROR| traceback:0013|     return func(*p_args, **p_dargs)
09/24 17:59:36 ERROR| traceback:0013|   File "/usr/local/autotest/tests/desktopui_UrlFetch/desktopui_UrlFetch.py", line 33, in cleanup
09/24 17:59:36 ERROR| traceback:0013|     super(desktopui_UrlFetch, self).cleanup()
09/24 17:59:36 ERROR| traceback:0013|   File "/usr/local/autotest/cros/cros_ui_test.py", line 464, in cleanup
09/24 17:59:36 ERROR| traceback:0013|     self.stop_authserver()
09/24 17:59:36 ERROR| traceback:0013|   File "/usr/local/autotest/cros/cros_ui_test.py", line 201, in stop_authserver
09/24 17:59:36 ERROR| traceback:0013|     self.revert_dns()
09/24 17:59:36 ERROR| traceback:0013|   File "/usr/local/autotest/cros/cros_ui_test.py", line 170, in revert_dns
09/24 17:59:36 ERROR| traceback:0013|     self.__alter_dns_for_device(device, self.__delete_dns_iptables_rule)
09/24 17:59:36 ERROR| traceback:0013|   File "/usr/local/autotest/cros/cros_ui_test.py", line 102, in __alter_dns_for_device
09/24 17:59:36 ERROR| traceback:0013|     dns_op(server, local_addr)
09/24 17:59:36 ERROR| traceback:0013|   File "/usr/local/autotest/cros/cros_ui_test.py", line 141, in __delete_dns_iptables_rule
09/24 17:59:36 ERROR| traceback:0013|     utils.system(self._IPTABLES_RULE % ('-D', original, replacement))
09/24 17:59:36 ERROR| traceback:0013|   File "/usr/local/autotest/common_lib/base_utils.py", line 897, in system
09/24 17:59:36 ERROR| traceback:0013|     stdout_tee=TEE_TO_LOGS, stderr_tee=TEE_TO_LOGS).exit_status
09/24 17:59:36 ERROR| traceback:0013|   File "/usr/local/autotest/common_lib/base_utils.py", line 658, in run
09/24 17:59:36 ERROR| traceback:0013|     "Command returned non-zero exit status")
09/24 17:59:36 ERROR| traceback:0013| CmdError: Command <iptables -t nat -D OUTPUT -p udp -d 10.0.2.3 --dport 53 -j DNAT --to-destination 10.0.2.15> failed, rc=1, Command returned non-zero exit status
09/24 17:59:36 ERROR| traceback:0013| * Command: 
09/24 17:59:36 ERROR| traceback:0013|     iptables -t nat -D OUTPUT -p udp -d 10.0.2.3 --dport 53 -j DNAT --to-
09/24 17:59:36 ERROR| traceback:0013|     destination 10.0.2.15
09/24 17:59:36 ERROR| traceback:0013| Exit status: 1
09/24 17:59:36 ERROR| traceback:0013| Duration: 0.19344997406
09/24 17:59:36 ERROR| traceback:0013| 
09/24 17:59:36 ERROR| traceback:0013| stderr:
09/24 17:59:36 ERROR| traceback:0013| iptables: No chain/target/match by that name.
09/24 17:59:36 ERROR|      test:0433| Now raising the earlier <class 'dbus.exceptions.DBusException'> error
Sep 25, 2011
#16 cmasone@chromium.org 
http://build.chromium.org/p/chromiumos/builders/x86%20generic%20full/builds/446/steps/VMTest/logs/stdio


16:19:29 INFO | 	START	desktopui_UrlFetch.not-live	desktopui_UrlFetch.not-live	timestamp=1316992769	localtime=Sep 25 16:19:29	
16:19:29 INFO | Bundling /build/x86-generic/usr/local/autotest/client/site_tests/desktopui_UrlFetch into test-desktopui_UrlFetch.tar.bz2
16:20:31 INFO | 		ERROR	desktopui_UrlFetch.not-live	desktopui_UrlFetch.not-live	timestamp=1316992831	localtime=Sep 25 16:20:31	Unhandled DBusException: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
16:20:31 INFO | 	END ERROR	desktopui_UrlFetch.not-live	desktopui_UrlFetch.not-live	timestamp=1316992831	localtime=Sep 25 16:20:31
Oct 18, 2011
#17 cmasone@chromium.org 
(No comment was entered for this change.)
Labels: Mstone-R17
Nov 11, 2011
#18 cmasone@chromium.org 
There has been a lot of change in this code, and we haven't seen this issue in about 6 weeks.
Status: WontFix
Apr 6, 2012
#19 dd...@chromium.org 
(No comment was entered for this change.)
Labels: -Mstone-R17 Mstone-17
Mar 6, 2013
#20 bugdroid1@chromium.org 
(No comment was entered for this change.)
Labels: OS-Chrome
Mar 9, 2013
#21 bugdroid1@chromium.org 
(No comment was entered for this change.)
Labels: -Area-Test -TreeCloser -Mstone-17 Cr-Test Hotlist-TreeCloser M-17
► Sign in to add a comment

Powered by Google Project Hosting