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

Issue 693694 link

Starred by 1 user
Status: Archived
Owner:
█ kirtika@chromium.org
Last visit > 30 days ago
Closed: Mar 2018
Cc:
mqg@chromium.org
█ shuqianz@chromium.org
adurbin@chromium.org
█ ejcaruso@chromium.org
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 2
Type: Bug



Sign in to add a comment

horrible shill spew Wr WrWr WrWrWr borks test

Project Member Reported by semenzato@chromium.org, Feb 17 2017 
https://pantheon.corp.google.com/storage/browser/chromeos-autotest-results/101764874-chromeos-test/chromeos4-row10-rack13-host7/sysinfo/var/log/

snippet from "messages":

2017-02-17T05:06:35.956036-08:00 INFO kernel: [  812.405335] IPv6: ADDRCONF(NETDEV_UP): tun0: link is not ready
2017-02-17T05:06:35.979744-08:00 INFO laptop-mode[13966]: Warning: Configuration file /etc/laptop-mode/conf.d/board-specific/*.conf is not readable, skipping.
2017-02-17T05:06:36.000209-08:00 INFO laptop-mode[13988]: Laptop mode 
2017-02-17T05:06:36.001723-08:00 INFO laptop-mode[13989]: enabled, not active
2017-02-17T05:06:36.066993-08:00 INFO kernel: [  812.516096] tpm_tis tpm_tis: command 0xa (size 10) returned code 0x0
2017-02-17T05:06:36.097292-08:00 INFO kernel: [  812.546563] tpm_tis tpm_tis: command 0x65 (size 18) returned code 0x0
2017-02-17T05:06:36.119047-08:00 ERR shill[1170]: [ERROR:error.cc(146)] [dns_client.cc(108)]: No valid DNS server addresses
2017-02-17T05:06:36.119101-08:00 ERR shill[1170]: [ERROR:http_request.cc(125)] Failed to start DNS client: No valid DNS server addresses
2017-02-17T05:06:36.313073-08:00 INFO kernel: [  812.763105] tpm_tis tpm_tis: command 0x3c (size 99) returned code 0x0
2017-02-17T05:06:36.344101-08:00 INFO kernel: [  812.793717] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2017-02-17T05:06:38.448590-08:00 INFO kernel: [  814.899854] IPv6: ADDRCONF(NETDEV_CHANGE): tun0: link becomes ready
2017-02-17T05:06:38.581007-08:00 WARNING kernel: [  815.032218] init: chapsd main process (13896) killed by TERM signal
2017-02-17T05:06:38.606912-08:00 INFO chapsd[14009]: Starting PKCS #11 services.
2017-02-17T05:06:38.607784-08:00 INFO chapsd[14009]: Starting D-Bus dispatcher.
2017-02-17T05:06:38.608326-08:00 INFO chapsd[14009]: Starting asynchronous initialization.
2017-02-17T05:06:38.611137-08:00 INFO kernel: [  815.062123] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x0
2017-02-17T05:06:38.641999-08:00 INFO kernel: [  815.093286] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x0
2017-02-17T05:06:38.678006-08:00 INFO kernel: [  815.129351] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x0
2017-02-17T05:06:38.701820-08:00 INFO chapsd[14009]: Adding slot: 0
2017-02-17T05:06:38.701864-08:00 INFO chapsd[14009]: Adding slot: 1
2017-02-17T05:06:38.702042-08:00 INFO kernel: [  815.153620] tpm_tis tpm_tis: command 0x46 (size 14) returned code 0x0
2017-02-17T05:06:38.727760-08:00 INFO chapsd[14009]: Opening database in: /var/lib/chaps
2017-02-17T05:06:38.728003-08:00 INFO kernel: [  815.179290] tpm_tis tpm_tis: command 0x46 (size 14) returned code 0x0
2017-02-17T05:06:38.755377-08:00 INFO chapsd[14009]: Slot 0 ready for token at /var/lib/chaps
2017-02-17T05:06:38.781994-08:00 INFO kernel: [  815.233314] tpm_tis tpm_tis: command 0xa (size 10) returned code 0x0
2017-02-17T05:06:38.836212-08:00 INFO kernel: [  815.287752] tpm_tis tpm_tis: command 0x65 (size 42) returned code 0x0
2017-02-17T05:06:39.820088-08:00 INFO kernel: [  816.272699] tpm_tis tpm_tis: command 0x41 (size 618) returned code 0x0
2017-02-17T05:06:39.851090-08:00 INFO kernel: [  816.303592] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2017-02-17T05:06:39.880086-08:00 INFO kernel: [  816.332644] tpm_tis tpm_tis: command 0xa (size 10) returned code 0x0
2017-02-17T05:06:39.911363-08:00 INFO kernel: [  816.363608] tpm_tis tpm_tis: command 0x65 (size 18) returned code 0x0
2017-02-17T05:06:40.379149-08:00 INFO kernel: [  816.831801] tpm_tis tpm_tis: command 0x1e (size 319) returned code 0x0
2017-02-17T05:06:40.409396-08:00 INFO chapsd[14009]: Master key is ready for token at /var/lib/chaps
2017-02-17T05:06:40.409729-08:00 INFO kernel: [  816.862017] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2017-02-17T05:06:40.746134-08:00 INFO avahi-daemon[1471]: Interface pseudoethernet0.IPv4 no longer relevant for mDNS.
2017-02-17T05:06:40.746172-08:00 INFO avahi-daemon[1471]: Leaving mDNS multicast group on interface pseudoethernet0.IPv4 with address 10.9.8.2.
2017-02-17T05:06:40.747547-08:00 ERR dhcpcd[13870]: pseudoethernet0: dhcp if_readrawpacket: Network is down
2017-02-17T05:06:40.750312-08:00 INFO avahi-daemon[1471]: Withdrawing address record for 10.9.8.2 on pseudoethernet0.
2017-02-17T05:06:40.755867-08:00 ERR shill[1170]: [ERROR:object_proxy.cc(582)] Failed to call method: org.chromium.dhcpcd.Release: object_path= /org/chromium/dhcpcd: org.freedesktop.DBus.Error.NoReply: Message did not receive a reply (timeout by message bus)
2017-02-17T05:06:40.755923-08:00 ERR shill[1170]: [ERROR:dbus_method_invoker.h(111)] CallMethodAndBlockWithTimeout(...): Domain=dbus, Code=org.freedesktop.DBus.Error.NoReply, Message=Message did not receive a reply (timeout by message bus)
2017-02-17T05:06:40.785553-08:00 ERR shill[1177]: WRWWWRRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWWWWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRRRRWRWRWRWRWRWRWRWRWRWRWWWWRRRRWRWRWWRRWRWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWRwrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWRwrWrWrWrWrWrWrWrWrWrWrWrWRwrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWr

The last line repeats MANY times, then we have this:

2017-02-17T05:07:12.048525-08:00 ERR shill[1177]: rWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWrWr
2017-02-17T05:07:12.060055-08:00 NOTICE autotest[14331]: 05:07:12.056 WARNI|virtual_ethernet_p:0129| VirtualEthernetPair.teardown() called, but no interface was found.
2017-02-17T05:07:12.163274-08:00 INFO kernel: [  848.640795] IPv6: ADDRCONF(NETDEV_UP): pseudoethernet0: link is not ready
2017-02-17T05:07:12.175996-08:00 INFO kernel: [  848.652091] IPv6: ADDRCONF(NETDEV_CHANGE): pseudoethernet0: link becomes ready
2017-02-17T05:07:12.175986-08:00 INFO laptop-mode[14357]: Warning: Configuration file /etc/laptop-mode/conf.d/board-specific/*.conf is not readable, skipping.
2017-02-17T05:07:12.176044-08:00 INFO laptop-mode[14358]: Warning: Configuration file /etc/laptop-mode/conf.d/board-specific/*.conf is not readable, skipping.
2017-02-17T05:07:12.211257-08:00 INFO avahi-daemon[1471]: Joining mDNS multicast group on interface serverethernet0.IPv4 with address 10.9.8.1.
2017-02-17T05:07:12.211718-08:00 INFO avahi-daemon[1471]: New relevant interface serverethernet0.IPv4 for mDNS.
2017-02-17T05:07:12.211747-08:00 INFO avahi-daemon[1471]: Registering new address record for 10.9.8.1 on serverethernet0.IPv4.
2017-02-17T05:07:12.211820-08:00 INFO avahi-daemon[1471]: Withdrawing address record for 10.9.8.1 on serverethernet0.
2017-02-17T05:07:12.211844-08:00 INFO avahi-daemon[1471]: Leaving mDNS multicast group on interface serverethernet0.IPv4 with address 10.9.8.1.
2017-02-17T05:07:12.212473-08:00 INFO avahi-daemon[1471]: Interface serverethernet0.IPv4 no longer relevant for mDNS.
2017-02-17T05:07:12.212518-08:00 INFO avahi-daemon[1471]: Joining mDNS multicast group on interface serverethernet0.IPv4 with address 10.9.8.1.
2017-02-17T05:07:12.212537-08:00 INFO avahi-daemon[1471]: New relevant interface serverethernet0.IPv4 for mDNS.
2017-02-17T05:07:12.212552-08:00 INFO avahi-daemon[1471]: Registering new address record for 10.9.8.1 on serverethernet0.IPv4.
2017-02-17T05:07:12.219630-08:00 INFO laptop-mode[14395]: Laptop mode 
2017-02-17T05:07:12.221135-08:00 INFO laptop-mode[14396]: enabled, not active
2017-02-17T05:07:12.222836-08:00 ERR laptop-mode[14390]: Couldn't acquire lock. Retrying.... PID is 14352\n
2017-02-17T05:07:12.233468-08:00 INFO avahi-daemon[1471]: Joining mDNS multicast group on interface pseudoethernet0.IPv4 with address 10.9.8.2.
2017-02-17T05:07:12.233704-08:00 INFO avahi-daemon[1471]: New relevant interface pseudoethernet0.IPv4 for mDNS.
2017-02-17T05:07:12.233724-08:00 INFO avahi-daemon[1471]: Registering new address record for 10.9.8.2 on pseudoethernet0.IPv4.
2017-02-17T05:07:12.233901-08:00 INFO avahi-daemon[1471]: Withdrawing address record for 10.9.8.2 on pseudoethernet0.
2017-02-17T05:07:12.233926-08:00 INFO avahi-daemon[1471]: Leaving mDNS multicast group on interface pseudoethernet0.IPv4 with address 10.9.8.2.
2017-02-17T05:07:12.234490-08:00 INFO avahi-daemon[1471]: Interface pseudoethernet0.IPv4 no longer relevant for mDNS.
2017-02-17T05:07:12.234530-08:00 INFO avahi-daemon[1471]: Joining mDNS multicast group on interface pseudoethernet0.IPv4 with address 10.9.8.2.
2017-02-17T05:07:12.234548-08:00 INFO avahi-daemon[1471]: New relevant interface pseudoethernet0.IPv4 for mDNS.
2017-02-17T05:07:12.234562-08:00 INFO avahi-daemon[1471]: Registering new address record for 10.9.8.2 on pseudoethernet0.IPv4.
2017-02-17T05:07:12.255926-08:00 INFO laptop-mode[14427]: Laptop mode 
2017-02-17T05:07:12.257450-08:00 INFO laptop-mode[14428]: enabled, not active
2017-02-17T05:07:12.360722-08:00 ERR shill[1170]: [ERROR:error.cc(146)] [dns_client.cc(108)]: No valid DNS server addresses
2017-02-17T05:07:12.360741-08:00 ERR shill[1170]: [ERROR:http_request.cc(125)] Failed to start DNS client: No valid DNS server addresses
2017-02-17T05:07:12.382923-08:00 INFO minijail0[14449]: libminijail[14449]: mount /bin -> /bin type ''

and then more spew:

2017-02-17T05:07:18.227125-08:00 ERR openvpn[14534]: TLS_ERROR: BIO read tls_read_plaintext error: error:14090086:SSL routines:ssl3_get_server_certificate:certificate verify failed
2017-02-17T05:07:18.227167-08:00 ERR openvpn[14534]: TLS Error: TLS object -> incoming plaintext read error
2017-02-17T05:07:18.227201-08:00 ERR openvpn[14534]: TLS Error: TLS handshake failed
2017-02-17T05:07:18.240227-08:00 ERR openvpn[14534]: TLS_ERROR: BIO read tls_read_plaintext error: error:14090086:SSL routines:ssl3_get_server_certificate:certificate verify failed
2017-02-17T05:07:18.240245-08:00 ERR openvpn[14534]: TLS Error: TLS object -> incoming plaintext read error
2017-02-17T05:07:18.240258-08:00 ERR openvpn[14534]: TLS Error: TLS handshake failed
2017-02-17T05:07:18.281589-08:00 ERR openvpn[14534]: TLS_ERROR: BIO read tls_read_plaintext error: error:14090086:SSL routines:ssl3_get_server_certificate:certificate verify failed
2017-02-17T05:07:18.281607-08:00 ERR openvpn[14534]: TLS Error: TLS object -> incoming plaintext read error
2017-02-17T05:07:18.281711-08:00 ERR openvpn[14534]: TLS Error: TLS handshake failed
2017-02-17T05:07:18.322702-08:00 ERR openvpn[14534]: TLS_ERROR: BIO read tls_read_plaintext error: error:14090086:SSL routines:ssl3_get_server_certificate:certificate verify failed
2017-02-17T05:07:18.322748-08:00 ERR openvpn[14534]: TLS Error: TLS object -> incoming plaintext read error
2017-02-17T05:07:18.322786-08:00 ERR openvpn[14534]: TLS Error: TLS handshake failed
2017-02-17T05:07:18.364234-08:00 ERR openvpn[14534]: TLS_ERROR: BIO read tls_read_plaintext error: error:14090086:SSL routines:ssl3_get_server_certificate:certificate verify failed
2017-02-17T05:07:18.364353-08:00 ERR openvpn[14534]: TLS Error: TLS object -> incoming plaintext read error

Comment 1 by semenzato@chromium.org, Feb 17 2017

Owner: kirtika@chromium.org
Kirtika can I bother you for a quick look at this?  Feel free to unassign after you comment.  Thanks!

Comment 2 by semenzato@chromium.org, Feb 17 2017 

For the record: this did not actually kill the test.  It got killed by something else.  Nevertheless, it may be worth a cursory investigation.

Comment 3 by benchan@chromium.org, Feb 17 2017 

Those WrWrWr... messages likely come from the stderr output from a child process spawn by shill. PID 1170 was the actual shill process.  PID 1177 that spew WrWrWr was the logger process with a log tag 'shill'.

shill runs a minijail'ed logger process to forward stderr output to syslog. When shill creates a child process, stderr from the child process may be forwarded to shill's stderr and then forwarded to the logger process, which ends up in the syslog.

Comment 4 by ayatane@chromium.org, Mar 10 2018

Status: Archived (was: Untriaged)
►

Sign in to add a comment