New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 673853 link

Starred by 1 user

Issue metadata

Status: Archived
Owner: ----
Closed: Mar 2018
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 3
Type: Bug



Sign in to add a comment

pubsubmonitor.send failures

Project Member Reported by semenzato@chromium.org, Dec 13 2016

Issue description

There are many of these in a job that failed for other reasons.  I don't think they have anything to do with the failure, and it would be slightly nicer if they didn't spew the logs, but I am filing this mostly for the record.


https://uberchromegw.corp.google.com/i/chromeos/builders/setzer-release/builds/665

https://pantheon.corp.google.com/storage/browser/chromeos-autotest-results/90428758-chromeos-test/chromeos4-row8-rack8-host3/debug/

12/13 05:27:26.621 DEBUG|        dev_server:1714| Current CrOS auto-update status: Transfer Devserver/Stateful Update Package
12/13 05:27:33.711 DEBUG|          monitors:0191| ts_mon: sending 12 metrics to PubSub
12/13 05:27:33.718 INFO |            client:0570| Attempting refresh to obtain initial access_token
12/13 05:27:33.758 INFO |            client:0872| Refreshing access_token
12/13 05:27:36.667 DEBUG|        base_utils:0185| Running 'ssh 100.115.219.130 'curl "http://100.115.219.130:8082/get_au_status?build_name=setzer-release/R57-9081.0.0&force_update=True&pid=7278&host_name=chromeos4-row8-rack8-host3&full_update=False"''
12/13 05:27:38.243 DEBUG|        dev_server:1714| Current CrOS auto-update status: transfer rootfs update package
12/13 05:27:43.809 WARNI|          monitors:0210| PubSubMonitor.send failed:
Traceback (most recent call last):
  File "/usr/local/autotest/site-packages/chromite/third_party/infra_libs/ts_mon/common/monitors.py", line 204, in send
    body=body).execute(num_retries=5)
  File "/usr/local/autotest/site-packages/chromite/third_party/oauth2client/util.py", line 140, in positional_wrapper
    return wrapped(*args, **kwargs)
  File "/usr/local/autotest/site-packages/chromite/third_party/googleapiclient/http.py", line 833, in execute
    method=str(self.method), body=self.body, headers=self.headers)
  File "/usr/local/autotest/site-packages/chromite/third_party/googleapiclient/http.py", line 160, in _retry_request
    resp, content = http.request(uri, method, *args, **kwargs)
  File "/usr/local/autotest/site-packages/chromite/third_party/oauth2client/client.py", line 572, in new_request
    self._refresh(request_orig)
  File "/usr/local/autotest/site-packages/chromite/third_party/oauth2client/client.py", line 842, in _refresh
    self._do_refresh_request(http_request)
  File "/usr/local/autotest/site-packages/chromite/third_party/oauth2client/client.py", line 874, in _do_refresh_request
    self.token_uri, method='POST', body=body, headers=headers)
  File "/usr/local/autotest/site-packages/chromite/third_party/infra_libs/httplib2_utils.py", line 198, in request
    uri, method, body, *args, **kwargs)
  File "/usr/local/autotest/site-packages/chromite/third_party/httplib2/__init__.py", line 1593, in request
    (response, content) = self._request(conn, authority, uri, request_uri, method, body, headers, redirections, cachekey)
  File "/usr/local/autotest/site-packages/chromite/third_party/httplib2/__init__.py", line 1335, in _request
    (response, content) = self._conn_request(conn, request_uri, method, body, headers)
  File "/usr/local/autotest/site-packages/chromite/third_party/httplib2/__init__.py", line 1257, in _conn_request
    conn.connect()
  File "/usr/local/autotest/site-packages/chromite/third_party/httplib2/__init__.py", line 1018, in connect
    sock.connect((self.host, self.port))
  File "/usr/lib/python2.7/socket.py", line 224, in meth
    return getattr(self._sock,name)(*args)
timeout: timed out

12/13 05:27:48.291 DEBUG|        base_utils:0185| Running 'ssh 100.115.219.130 'curl "http://100.115.219.130:8082/get_au_status?build_name=setzer-release/R57-9081.0.0&force_update=True&pid=7278&host_name=chromeos4-row8-rack8-host3&full_update=False"''
12/13 05:27:50.185 DEBUG|        dev_server:1714| Current CrOS auto-update status: transfer rootfs update package
 
Cc: pho...@chromium.org
Labels: Hotlist-Fixit
Also for pubsubmonitor._initialize.

It would also be good to log that these are recoverable errors.  Otherwise the poor sheriff has no idea.

https://uberchromegw.corp.google.com/i/chromeos/builders/edgar-release/builds/734/steps/HWTest%20%5Bsanity%5D/logs/stdio

https://pantheon.corp.google.com/storage/browser/chromeos-autotest-results/94501594-chromeos-test/chromeos4-row12-rack8-host3/debug/

see autoserv.DEBUG
Labels: Logging-improv
Cc: hidehiko@chromium.org
Re #2: So it is already WARNING, but not ERROR, maybe what needed is just saying "recovering..." in the line?

Or, maybe split the log into two lines, saying 1) PubSubMonitor method is failed with WARNING log level, then 2) with stacktrace with DEBUG log level?
Status: Archived (was: Untriaged)
This bug is very old, is Untriaged, and has no owner.  If it is still relevant, reopen as Untriaged or open a new bug

Sign in to add a comment