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

Issue 872829 link

Starred by 1 user
Status: Verified
Owner: ----
Closed: Aug 9
Cc:
█ jmuppala@chromium.org
briannorris@chromium.org
dsunk...@chromium.org
█ kirtika@chromium.org
harpreet@chromium.org
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 2
Type: Bug



Sign in to add a comment

Pantheon (Nami) failing simpleconnect testcases : Cannot find device 'monitor0'

Project Member Reported by aashuto...@chromium.org, Aug 9

Comment 1 by harpreet@chromium.org, Aug 9

Cc: briannorris@chromium.org kirtika@chromium.org
Summary: Pantheon (Nami) failing simpleconnect testcases : Cannot find device 'monitor0' (was: Pantheon (Nami) failing simpleconnect testcases )
It only seems to be affecting Pantheon. Looks like simpleconnect tests started failing with R68-10718.71.2 on this board with "Cannot find device 'monitor0'".

https://stainless.corp.google.com/search?view=matrix&row=board_model&col=build&first_date=2018-06-13&last_date=2018-08-09&suite=wifi_release&test=%5Enetwork_WiFi_SimpleConnect&board=%5Enami&status=GOOD&status=WARN&status=FAIL&status=ERROR&status=ABORT&status=ALERT&status=RUNNING&status=TEST_NA&status=NOSTATUS&status=NOT_RUN&exclude_cts=true&exclude_not_run=false&exclude_non_release=true&exclude_au=true&exclude_acts=true&exclude_retried=true&exclude_non_production=true







08/09 08:31:28.371 INFO | site_linux_router:0292| Starting hostapd on managed0(phy1) channel=48...
08/09 08:31:28.378 DEBUG|          ssh_host:0301| Running (ssh) 'rm /tmp/hostapd-test-managed0.log' from 'run_once|configure|hostap_configure|start_hostapd|run|run_very_slowly'
08/09 08:31:28.793 DEBUG|          ssh_host:0301| Running (ssh) 'stop wpasupplicant' from 'run_once|configure|hostap_configure|start_hostapd|run|run_very_slowly'
08/09 08:31:29.279 DEBUG|             utils:0287| [stderr] stop: Unknown instance: 
08/09 08:31:29.292 DEBUG|          ssh_host:0301| Running (ssh) '/usr/sbin/hostapd -dd -t /tmp/hostapd-test-managed0.conf > /tmp/hostapd-test-managed0.log 2> /tmp/hostapd-stderr-test-managed0.log & echo $!' from 'run_once|configure|hostap_configure|start_hostapd|run|run_very_slowly'
08/09 08:31:29.723 DEBUG|             utils:0287| [stdout] 18795
08/09 08:31:29.729 INFO | site_linux_router:0308| Waiting for hostapd to startup.
08/09 08:31:29.738 DEBUG|          ssh_host:0301| Running (ssh) 'grep "Setup of interface done" /tmp/hostapd-test-managed0.log' from 'start_hostapd|poll_for_condition|<lambda>|_has_hostapd_started|run|run_very_slowly'
08/09 08:31:31.256 DEBUG|             utils:0287| [stdout] 1533828690.515456: managed0: Setup of interface done.
08/09 08:31:31.266 DEBUG|          ssh_host:0301| Running (ssh) '/usr/sbin/iw dev managed0 set txpower auto' from 'run_once|configure|hostap_configure|set_tx_power|run|run_very_slowly'
08/09 08:31:31.749 DEBUG|          ssh_host:0301| Running (ssh) '/usr/sbin/iw dev' from 'hostap_configure|set_beacon_footer|get_interface|list_interfaces|run|run_very_slowly'
08/09 08:31:32.181 DEBUG|             utils:0287| [stdout] phy#1
08/09 08:31:32.182 DEBUG|             utils:0287| [stdout] 	Interface managed0
08/09 08:31:32.182 DEBUG|             utils:0287| [stdout] 		ifindex 1477
08/09 08:31:32.182 DEBUG|             utils:0287| [stdout] 		wdev 0x10000017e
08/09 08:31:32.182 DEBUG|             utils:0287| [stdout] 		addr a4:2b:b0:b7:e6:f7
08/09 08:31:32.182 DEBUG|             utils:0287| [stdout] 		ssid SimpleConnect_a_ksedn_ch48
08/09 08:31:32.182 DEBUG|             utils:0287| [stdout] 		type AP
08/09 08:31:32.182 DEBUG|             utils:0287| [stdout] 		channel 48 (5240 MHz), width: 20 MHz, center1: 5240 MHz
08/09 08:31:32.190 DEBUG|          ssh_host:0301| Running (ssh) 'test -e /sys/kernel/debug/ieee80211/phy1/beacon_footer' from 'run_once|configure|hostap_configure|set_beacon_footer|run|run_very_slowly'
08/09 08:31:32.606 INFO | site_linux_router:1164| Beacon footer file does not exist.  Ignoring.
08/09 08:31:32.607 INFO | site_linux_router:0598| Starting up local server...
08/09 08:31:32.621 DEBUG|          ssh_host:0301| Running (ssh) '/bin/ip addr flush managed0' from 'run_once|configure|hostap_configure|start_local_server|run|run_very_slowly'
08/09 08:31:33.133 DEBUG|          ssh_host:0301| Running (ssh) '/bin/ip addr add 192.168.0.254/24 broadcast 192.168.0.255 dev managed0' from 'run_once|configure|hostap_configure|start_local_server|run|run_very_slowly'
08/09 08:31:33.605 DEBUG|          ssh_host:0301| Running (ssh) '/bin/ip link set managed0 up' from 'run_once|configure|hostap_configure|start_local_server|run|run_very_slowly'
08/09 08:31:34.078 DEBUG|          ssh_host:0301| Running (ssh) 'cat <<EOF >/tmp/dhcpd.managed0.conf
port=0
bind-interfaces
log-dhcp
dhcp-range=192.168.0.1,192.168.0.128
interface=managed0
dhcp-leasefile=/tmp/dhcpd.leases
EOF
' from 'configure|hostap_configure|start_local_server|start_dhcp_server|run|run_very_slowly'
08/09 08:31:34.536 DEBUG|          ssh_host:0301| Running (ssh) 'dnsmasq --conf-file=/tmp/dhcpd.managed0.conf' from 'configure|hostap_configure|start_local_server|start_dhcp_server|run|run_very_slowly'
08/09 08:31:34.939 INFO | site_linux_router:0480| AP configured.
08/09 08:31:34.939 DEBUG| site_linux_system:0396| Filtering out phy2, which reports only 1 antennas
08/09 08:31:34.946 DEBUG|          ssh_host:0301| Running (ssh) '/usr/sbin/iw phy phy1 interface add monitor0 type monitor' from 'start_capture|get_wlanif|_get_wlanif|add_interface|run|run_very_slowly'
08/09 08:31:35.341 DEBUG|          ssh_host:0301| Running (ssh) '/bin/ip link set dev monitor0 down' from 'run_once|start_capture|get_wlanif|_get_wlanif|run|run_very_slowly'
08/09 08:31:36.912 ERROR|             utils:0287| [stderr] Cannot find device "monitor0"
08/09 08:31:36.915 DEBUG|              test:0410| Test failed due to command execution error
* Command: 
    /usr/bin/ssh -a -x   -o Protocol=2 -o StrictHostKeyChecking=no -o
    UserKnownHostsFile=/dev/null -o BatchMode=yes -o ConnectTimeout=30 -o
    ServerAliveInterval=900 -o ServerAliveCountMax=3 -o ConnectionAttempts=4
    -l root -p 22 chromeos15-row4-rack11-host2-pcap "export
    LIBC_FATAL_STDERR_=1; if type \"logger\" > /dev/null 2>&1; then logger
    -tag \"autotest\" \"server[stack::get_wlanif|_get_wlanif|run] ->
    ssh_run(/bin/ip link set dev monitor0 down)\";fi; /bin/ip link set dev
    monitor0 down"
Exit status: 1
Duration: 1.56239295006

stderr:
Cannot find device "monitor0". Exception log follows the after_iteration_hooks.
08/09 08:31:36.916 DEBUG|              test:0415| Starting after_iteration_hooks for network_WiFi_SimpleConnect.wifi_check5HT20
08/09 08:31:36.923 DEBUG|          ssh_host:0301| Running (ssh) 'test -e "/tmp/sysinfo/autoserv-LZi35p"' from 'decorated_func|wrapper|_install|path_exists|run|run_very_slowly'
08/09 08:31:37.225 DEBUG|          ssh_host:0301| Running (ssh) 'test -e "/tmp/autoserv-lURGTF"' from 'decorated_func|wrapper|_install|path_exists|run|run_very_slowly'
08/09 08:31:37.539 DEBUG|          ssh_host:0301| Running (ssh) 'find "/tmp/autoserv-lURGTF" -mindepth 1 -maxdepth 1 -print0 | xargs -0 rm -rf' from '_call_run_once|decorated_func|wrapper|erase_dir_contents|run|run_very_slowly'
08/09 08:31:37.829 DEBUG|      abstract_ssh:0520| send_file. source: /tmp/tmpGE8et_, dest: /tmp/autoserv-lURGTF/sysinfo.pickle, delete_dest: False,preserve_symlinks:False
08/09 08:31:37.829 DEBUG|      abstract_ssh:0537| Using Rsync.
08/09 08:31:37.829 DEBUG|             utils:0219| Running 'rsync -L  --timeout=1800 --rsh='/usr/bin/ssh -a -x  -o Protocol=2 -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o BatchMode=yes -o ConnectTimeout=30 -o ServerAliveInterval=900 -o ServerAliveCountMax=3 -o ConnectionAttempts=4 -l root -p 22' -az --no-o --no-g  "/tmp/tmpGE8et_" "root@chromeos15-row4-rack11-host2:"/tmp/autoserv-lURGTF/sysinfo.pickle""'
08/09 08:31:38.275 DEBUG|          ssh_host:0301| Running (ssh) 'true' from '_get_host_and_setup|wait_up|is_up|ssh_ping|run|run_very_slowly'
08/09 08:31:38.571 DEBUG|      abstract_ssh:0670| Host chromeos15-row4-rack11-host2 is now up
08/09 08:31:38.571 DEBUG|          autotest:0468| Autotest job starts on remote host: chromeos15-row4-rack11-host2
08/09 08:31:38.571 DEBUG|          autotest:0128| Using existing host autodir: /tmp/sysinfo/autoserv-LZi35p
08/09 08:31:38.580 DEBUG|          ssh_host:0301| Running (ssh) 'ls /tmp/sysinfo/autoserv-LZi35p/bin/autotest > /dev/null 2>&1' from 'after_iteration_hook|run|_do_run|verify_machine|run|run_very_slowly'
08/09 08:31:38.917 DEBUG|          ssh_host:0301| Running (ssh) 'umount /tmp/sysinfo/autoserv-LZi35p/tmp' from 'after_iteration_hook|run|_do_run|verify_machine|run|run_very_slowly'
08/09 08:31:39.240 DEBUG|             utils:0287| [stderr] umount: /tmp/sysinfo/autoserv-LZi35p/tmp: not mounted
08/09 08:31:39.303 DEBUG|          ssh_host:0301| Running (ssh) 'umount /tmp/sysinfo/autoserv-LZi35p/tests/download' from 'after_iteration_hook|run|_do_run|verify_machine|run|run_very_slowly'
08/09 08:31:39.674 DEBUG|             utils:0287| [stderr] umount: /tmp/sysinfo/autoserv-LZi35p/tests/download: not mounted
08/09 08:31:39.687 DEBUG|          ssh_host:0301| Running (ssh) 'rm -f /tmp/sysinfo/autoserv-LZi35p/control.autoserv;rm -f /tmp/sysinfo/autoserv-LZi35p/control.autoserv.state;rm -f /tmp/sysinfo/autoserv-LZi35p/control;rm -f /tmp/sysinfo/autoserv-LZi35p/control.state' from 'wrapper|after_iteration_hook|run|_do_run|run|run_very_slowly'
08/09 08:31:40.002 INFO |          autotest:0245| Got job repo url from host attributes: http://100.115.127.248:8082/static/nami-release/R69-10895.18.0/autotest/packages
08/09 08:31:40.003 DEBUG|          base_job:0357| Persistent state client.sysinfo now set to {'test': set([site_sysinfo.logdir('/tmp/crash_reporter', ('**autoserv*',)), site_sysinfo.logdir('/home/chronos/user/log', ('**autoserv*',)), sysinfo.logfile('/home/chronos/.Google/Google Talk Plugin/gtbplugin.log', 'gtbplugin.log', False), site_sysinfo.logdir('/var/spool/crash', ('**autoserv*', '*.core')), sysinfo.command('dmesg -c', 'dmesg', False), sysinfo.command('df -mP', 'df', False), sysinfo.command('journalctl -o export', 'journal', False)]), 'boot': set([sysinfo.command('hostname', 'hostname', False), sysinfo.logfile('/proc/interrupts', 'interrupts', False), sysinfo.command('uname -a', 'uname', True), sysinfo.logfile('/proc/version', 'version', False), sysinfo.command('lspci -vvn', 'lspci_-vvn', False), sysinfo.command('crossystem', 'crossystem', False), sysinfo.logfile('/proc/modules', 'modules', False), sysinfo.logfile('/var/log/messages', 'messages', False), sysinfo.command('ls -l /boot', 'boot_file_list', False), sysinfo.logfile('/proc/pci', 'pci', False), sysinfo.logfile('/proc/meminfo', 'meminfo', False), sysinfo.command('gcc --version', 'gcc_--version', False), sysinfo.logfile('/proc/mounts', 'proc_mounts', False), sysinfo.logfile('/proc/cpuinfo', 'cpuinfo', False), sysinfo.logfile('/proc/slabinfo', 'slabinfo', False), sysinfo.command('ld --version', 'ld_--version', False), sysinfo.logfile('/proc/partitions', 'partitions', False), sysinfo.command('mount', 'mount', False), sysinfo.logfile('/proc/cmdline', 'cmdline', True), sysinfo.logfile('/var/log/bios_info.txt', 'bios_info.txt', False), sysinfo.logfile('/var/log/storage_info.txt', 'storage_info.txt', False), sysinfo.command('uptime', 'uptime', False), sysinfo.logfile('/sys/fs/pstore', 'pstore', False)])}
08/09 08:31:40.004 DEBUG|      abstract_ssh:0520| send_file. source: /tmp/tmpp0vK2U, dest: /tmp/sysinfo/autoserv-LZi35p/control.autoserv.init.state, delete_dest: False,preserve_symlinks:False
08/09 08:31:40.004 DEBUG|      abstract_ssh:0537| Using Rsync.
08/09 08:31:40.005 DEBUG|             utils:0219| Running 'rsync -L  --timeout=1800 --rsh='/usr/bin/ssh -a -x  -o Protocol=2 -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o BatchMode=yes -o ConnectTimeout=30 -o ServerAliveInterval=900 -o ServerAliveCountMax=3 -o ConnectionAttempts=4 -l root -p 22' -az --no-o --no-g  "/tmp/tmpp0vK2U" "root@chromeos15-row4-rack11-host2:"/tmp/sysinfo/autoserv-LZi35p/control.autoserv.init.state""'
08/09 08:31:40.440 DEBUG|      abstract_ssh:0520| send_file. source: /tmp/autoserv-sXVKFR/tmpjgRpbr, dest: /tmp/sysinfo/autoserv-LZi35p/control.autoserv, delete_dest: False,preserve_symlinks:False
08/09 08:31:40.441 DEBUG|      abstract_ssh:0537| Using Rsync.
08/09 08:31:40.441 DEBUG|             utils:0219| Running 'rsync -L  --timeout=1800 --rsh='/usr/bin/ssh -a -x  -o Protocol=2 -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o BatchMode=yes -o ConnectTimeout=30 -o ServerAliveInterval=900 -o ServerAliveCountMax=3 -o ConnectionAttempts=4 -l root -p 22' -az --no-o --no-g  "/tmp/autoserv-sXVKFR/tmpjgRpbr" "root@chromeos15-row4-rack11-host2:"/tmp/sysinfo/autoserv-LZi35p/control.autoserv""'
08/09 08:31:40.881 DEBUG|          ssh_host:0301| Running (ssh) 'if [ -f '/proc/sys/kernel/random/boot_id' ]; then cat '/proc/sys/kernel/random/boot_id'; else echo 'no boot_id available'; fi' from 'run|_do_run|execute_control|get_boot_id|run|run_very_slowly'
08/09 08:31:41.222 DEBUG|             utils:0287| [stdout] 8c6041d9-11b2-4389-861b-1eca59d4e0b0
08/09 08:31:41.224 INFO |          autotest:0974| Executing /tmp/sysinfo/autoserv-LZi35p/bin/autotest /tmp/sysinfo/autoserv-LZi35p/control phase 0
08/09 08:31:41.237 DEBUG|          ssh_host:0301| Running (ssh) 'mkdir -p /tmp' from 'execute_control|execute_section|_execute_daemon|get_tmp_dir|run|run_very_slowly'
08/09 08:31:41.573 DEBUG|          ssh_host:0301| Running (ssh) 'mktemp -d /tmp/autoserv-XXXXXX' from 'execute_control|execute_section|_execute_daemon|get_tmp_dir|run|run_very_slowly'
08/09 08:31:41.873 DEBUG|             utils:0287| [stdout] /tmp/autoserv-QseD3V
08/09 08:31:41.921 DEBUG|      abstract_ssh:0520| send_file. source: /tmp/tmpKPK9qM, dest: /tmp/sysinfo/autoserv-LZi35p/global_config.ini, delete_dest: False,preserve_symlinks:False
08/09 08:31:41.921 DEBUG|      abstract_ssh:0537| Using Rsync.
08/09 08:31:41.921 DEBUG|             utils:0219| Running 'rsync -L  --timeout=1800 --rsh='/usr/bin/ssh -a -x  -o Protocol=2 -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o BatchMode=yes -o ConnectTimeout=30 -o ServerAliveInterval=900 -o ServerAliveCountMax=3 -o ConnectionAttempts=4 -l root -p 22' -az --no-o --no-g  "/tmp/tmpKPK9qM" "root@chromeos15-row4-rack11-host2:"/tmp/sysinfo/autoserv-LZi35p/global_config.ini""'
08/09 08:31:42.347 DEBUG|          ssh_host:0301| Running (ssh) 'nohup /tmp/sysinfo/autoserv-LZi35p/bin/autotestd /tmp/autoserv-QseD3V -H autoserv --verbose --hostname=chromeos15-row4-rack11-host2 --user=chromeos-test /tmp/sysinfo/autoserv-LZi35p/control.autoserv >/dev/null 2>/dev/null &' from '_do_run|execute_control|execute_section|_execute_daemon|run|run_very_slowly'
08/09 08:31:42.648 DEBUG|          ssh_host:0301| Running (ssh) '/tmp/sysinfo/autoserv-LZi35p/bin/autotestd_monitor /tmp/autoserv-QseD3V 0 0' from '_do_run|execute_control|execute_section|_execute_daemon|run|run_very_slowly'
08/09 08:31:42.985 DEBUG|          autotest:1281| AUTOTEST_STATUS::START	----	----	timestamp=1533828702	localtime=Aug 09 08:31:42	
08/09 08:31:42.986 INFO |        server_job:0216| 	START	----	----	timestamp=1533828702	localtime=Aug 09 08:31:42	
08/09 08:31:42.986 DEBUG|          autotest:1281| AUTOTEST_STATUS::	GOOD	----	sysinfo.iteration.after	timestamp=1533828702	localtime=Aug 09 08:31:42	
08/09 08:31:42.986 INFO |        server_job:0216| 		GOOD	----	sysinfo.iteration.after	timestamp=1533828702	localtime=Aug 09 08:31:42	
08/09 08:31:42.987 DEBUG|          autotest:1281| AUTOTEST_STATUS::END GOOD	----	----	timestamp=1533828702	localtime=Aug 09 08:31:42	
08/09 08:31:42.987 INFO |        server_job:0216| 	END GOOD	----	----	timestamp=1533828702	localtime=Aug 09 08:31:42	
08/09 08:31:42.987 DEBUG|          autotest:1281| Entered autotestd_monitor.
08/09 08:31:42.988 INFO |          autotest:1340| Entered autotestd_monitor.
08/09 08:31:42.988 DEBUG|          autotest:1281| Finished launching tail subprocesses.
08/09 08:31:42.988 INFO |          autotest:1340| Finished launching tail subprocesses.
08/09 08:31:42.988 DEBUG|          autotest:1281| Finished waiting on autotestd to start.
08/09 08:31:42.988 INFO |          autotest:1340| Finished waiting on autotestd to start.
08/09 08:31:42.988 DEBUG|          autotest:1281| Got lock of exit_code_file.
08/09 08:31:42.988 INFO |          autotest:1340| Got lock of exit_code_file.
08/09 08:31:42.989 DEBUG|          autotest:1281| Released lock of exit_code_file and closed it.
08/09 08:31:42.989 INFO |          autotest:1340| Released lock of exit_code_file and closed it.
08/09 08:31:44.949 DEBUG|          autotest:0956| Result exit status is 0.
08/09 08:31:44.950 INFO |          autotest:1059| Client complete
08/09 08:31:44.950 DEBUG|          autotest:1108| Autotest job finishes running. Below is the post-processing operations.
08/09 08:31:44.960 DEBUG|          ssh_host:0301| Running (ssh) 'true' from 'collect_client_job_results|wait_up|is_up|ssh_ping|run|run_very_slowly'
08/09 08:31:45.352 DEBUG|      abstract_ssh:0670| Host chromeos15-row4-rack11-host2 is now up
08/09 08:31:45.353 DEBUG|            runner:0089| result tools are already deployed to chromeos15-row4-rack11-host2.
08/09 08:31:45.353 DEBUG|            runner:0100| Getting directory summary for /tmp/sysinfo/autoserv-LZi35p/results/default
08/09 08:31:45.364 DEBUG|          ssh_host:0301| Running (ssh) '/usr/local/autotest/result_tools/utils.py -p /tmp/sysinfo/autoserv-LZi35p/results/default -m 20000' from '_do_run|execute_control|collect_client_job_results|run_on_client|run|run_very_slowly'
08/09 08:31:45.713 DEBUG|             utils:0287| [stdout] 2018-08-09 08:31:45,638 Running result_tools/utils on path: /tmp/sysinfo/autoserv-LZi35p/results/default
08/09 08:31:45.714 DEBUG|             utils:0287| [stdout] 2018-08-09 08:31:45,638 Throttle result size to : 19 MB
08/09 08:31:45.764 DEBUG|             utils:0287| [stdout] 2018-08-09 08:31:45,640 Directory summary of /tmp/sysinfo/autoserv-LZi35p/results/default is saved to file /tmp/sysinfo/autoserv-LZi35p/results/default/dir_summary_1533828705.json.
08/09 08:31:45.764 DEBUG|             utils:0287| [stdout] 2018-08-09 08:31:45,640 Skip throttling /tmp/sysinfo/autoserv-LZi35p/results/default: size=5467433, throttle_probability=3.74581636391
08/09 08:31:45.767 DEBUG|      abstract_ssh:0413| get_file. source: /tmp/sysinfo/autoserv-LZi35p/results/default/, dest: /usr/local/autotest/results/225045962-chromeos-test, delete_dest: False,preserve_perm: True, preserve_symlinks:True
08/09 08:31:45.767 DEBUG|      abstract_ssh:0425| Using Rsync.
08/09 08:31:45.768 DEBUG|             utils:0219| Running 'rsync -l  --timeout=1800 --rsh='/usr/bin/ssh -a -x  -o Protocol=2 -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o BatchMode=yes -o ConnectTimeout=30 -o ServerAliveInterval=900 -o ServerAliveCountMax=3 -o ConnectionAttempts=4 -l root -p 22' -az --no-o --no-g  root@chromeos15-row4-rack11-host2:"/tmp/sysinfo/autoserv-LZi35p/results/default/" "/usr/local/autotest/results/225045962-chromeos-test"'
08/09 08:31:46.553 DEBUG|          base_job:0250| Value of client.sysinfo is unchanged, skipping import
08/09 08:31:46.553 DEBUG|          base_job:0253| Importing client.harness from state file /usr/local/autotest/results/225045962-chromeos-test/control.autoserv.state
08/09 08:31:46.553 DEBUG|          base_job:0253| Importing client.steps from state file /usr/local/autotest/results/225045962-chromeos-test/control.autoserv.state
08/09 08:31:46.553 DEBUG|          base_job:0253| Importing client._record_indent from state file /usr/local/autotest/results/225045962-chromeos-test/control.autoserv.state
08/09 08:31:46.553 DEBUG|          base_job:0250| Value of global_properties.max_result_size_KB is unchanged, skipping import
08/09 08:31:46.553 DEBUG|          base_job:0250| Value of global_properties.tag is unchanged, skipping import
08/09 08:31:46.553 DEBUG|          base_job:0250| Value of global_properties.test_retry is unchanged, skipping import
08/09 08:31:46.554 DEBUG|          base_job:0250| Value of global_properties.fast is unchanged, skipping import
08/09 08:31:46.554 DEBUG|          base_job:0399| Persistent state client.* deleted
08/09 08:31:46.555 DEBUG|          autotest:1122| Autotest job finishes.
08/09 08:31:46.555 DEBUG|      abstract_ssh:0413| get_file. source: /tmp/autoserv-lURGTF/sysinfo.pickle, dest: /tmp/tmpRxQmmV, delete_dest: False,preserve_perm: True, preserve_symlinks:False
08/09 08:31:46.556 DEBUG|      abstract_ssh:0425| Using Rsync.
08/09 08:31:46.556 DEBUG|             utils:0219| Running 'rsync -L  --timeout=1800 --rsh='/usr/bin/ssh -a -x  -o Protocol=2 -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o BatchMode=yes -o ConnectTimeout=30 -o ServerAliveInterval=900 -o ServerAliveCountMax=3 -o ConnectionAttempts=4 -l root -p 22' -az --no-o --no-g  root@chromeos15-row4-rack11-host2:"/tmp/autoserv-lURGTF/sysinfo.pickle" "/tmp/tmpRxQmmV"'
08/09 08:31:46.986 DEBUG|              test:0420| after_iteration_hooks completed
08/09 08:31:46.988 WARNI|              test:0637| The test failed with the following exception
Traceback (most recent call last):
  File "/usr/local/autotest/client/common_lib/test.py", line 631, in _exec
    _call_test_function(self.execute, *p_args, **p_dargs)
  File "/usr/local/autotest/client/common_lib/test.py", line 837, in _call_test_function
    raise error.UnhandledTestFail(e)
UnhandledTestFail: Unhandled AutoservRunError: command execution error
* Command: 
    /usr/bin/ssh -a -x   -o Protocol=2 -o StrictHostKeyChecking=no -o
    UserKnownHostsFile=/dev/null -o BatchMode=yes -o ConnectTimeout=30 -o
    ServerAliveInterval=900 -o ServerAliveCountMax=3 -o ConnectionAttempts=4
    -l root -p 22 chromeos15-row4-rack11-host2-pcap "export
    LIBC_FATAL_STDERR_=1; if type \"logger\" > /dev/null 2>&1; then logger
    -tag \"autotest\" \"server[stack::get_wlanif|_get_wlanif|run] ->
    ssh_run(/bin/ip link set dev monitor0 down)\";fi; /bin/ip link set dev
    monitor0 down"
Exit status: 1
Duration: 1.56239295006

stderr:
Cannot find device "monitor0"
Traceback (most recent call last):
  File "/usr/local/autotest/client/common_lib/test.py", line 831, in _call_test_function
    return func(*args, **dargs)
  File "/usr/local/autotest/client/common_lib/test.py", line 495, in execute
    dargs)
  File "/usr/local/autotest/client/common_lib/test.py", line 362, in _call_run_once_with_retry
    postprocess_profiled_run, args, dargs)
  File "/usr/local/autotest/client/common_lib/test.py", line 400, in _call_run_once
    self.run_once(*args, **dargs)
  File "/usr/local/autotest/server/site_tests/network_WiFi_SimpleConnect/network_WiFi_SimpleConnect.py", line 31, in run_once
    ht_type=router_conf.ht_packet_capture_mode)
  File "/usr/local/autotest/server/site_linux_system.py", line 319, in start_capture
    self._capture_interface = self.get_wlanif(frequency, 'monitor')
  File "/usr/local/autotest/server/site_linux_system.py", line 547, in get_wlanif
    phytype, spatial_streams, frequency, same_phy_as)
  File "/usr/local/autotest/server/site_linux_system.py", line 477, in _get_wlanif
    self.cmd_ip, net_dev.if_name))
  File "/usr/local/autotest/server/hosts/ssh_host.py", line 323, in run
    return self.run_very_slowly(*args, **kwargs)
  File "/usr/local/autotest/server/hosts/ssh_host.py", line 312, in run_very_slowly
    ssh_failure_retry_ok)
  File "/usr/local/autotest/server/hosts/ssh_host.py", line 262, in _run
    raise error.AutoservRunError("command execution error", result)
AutoservRunError: command execution error
* Command: 
    /usr/bin/ssh -a -x   -o Protocol=2 -o StrictHostKeyChecking=no -o
    UserKnownHostsFile=/dev/null -o BatchMode=yes -o ConnectTimeout=30 -o
    ServerAliveInterval=900 -o ServerAliveCountMax=3 -o ConnectionAttempts=4
    -l root -p 22 chromeos15-row4-rack11-host2-pcap "export
    LIBC_FATAL_STDERR_=1; if type \"logger\" > /dev/null 2>&1; then logger
    -tag \"autotest\" \"server[stack::get_wlanif|_get_wlanif|run] ->
    ssh_run(/bin/ip link set dev monitor0 down)\";fi; /bin/ip link set dev
    monitor0 down"
Exit status: 1
Duration: 1.56239295006

stderr:
Cannot find device "monitor0"

08/09 08:31:46.989 DEBUG|              test:0642| Running cleanup for test.
08/09 08:31:46.989 INFO |       wifi_client:1318| ======= WiFi autotest complete. Cleaning up... =======

Comment 2 by aashuto...@chromium.org, Aug 9

Status: Verified (was: Untriaged)
The issue was due to pcap having older image. Upgrading the pcap to the latest M65 fixed the problem.
Verified by the regression by running the following job. 

AFE, logs	225045921	2018-08-08 14:20:55	2018-08-09 14:22:01	3m16s	wifi_release	nami	pantheon	R69-10895.18.0	network_WiFi_SimpleConnect.wifi_checkWPA2	FAIL	Unhandled AutoservRunError: command execution error

After upgrading pcap 
---------------------------------------------------------------------------------------------------------------------------------------------
/tmp/test_that_results_wn6AXF/results-1-network_WiFi_SimpleConnect.wifi_check1x_PEAP                                              [  PASSED  ]
/tmp/test_that_results_wn6AXF/results-1-network_WiFi_SimpleConnect.wifi_check1x_PEAP/network_WiFi_SimpleConnect.wifi_check1x_PEAP [  PASSED  ]
---------------------------------------------------------------------------------------------------------------------------------------------
Total PASS: 2/2 (100%)

Comment 3 by aashuto...@chromium.org, Aug 9 

The issue was due to pcap having older image. Upgrading the pcap to the latest M65 fixed the problem.
Verified  by running the previously failing  job on the same build. 

AFE, logs	225045921	2018-08-08 14:20:55	2018-08-09 14:22:01	3m16s	wifi_release	nami	pantheon	R69-10895.18.0	network_WiFi_SimpleConnect.wifi_checkWPA2	FAIL	Unhandled AutoservRunError: command execution error

After upgrading pcap 
---------------------------------------------------------------------------------------------------------------------------------------------
/tmp/test_that_results_wn6AXF/results-1-network_WiFi_SimpleConnect.wifi_check1x_PEAP                                              [  PASSED  ]
/tmp/test_that_results_wn6AXF/results-1-network_WiFi_SimpleConnect.wifi_check1x_PEAP/network_WiFi_SimpleConnect.wifi_check1x_PEAP [  PASSED  ]
---------------------------------------------------------------------------------------------------------------------------------------------
Total PASS: 2/2 (100%)
►

Sign in to add a comment