Warning message being captured when there is no setting loglevel to quiet

[LiaoU3]

Description

JSONDecodeError pop up when provisioning through sdwire.

Device: https://certification.canonical.com/hardware/202311-32317/
Job: https://testflinger.canonical.com/jobs/7d500571-48e0-4402-9af8-bf4695ac897c

testflinger yaml

job_queue: 202311-32317
provision_data:
  url: http://10.102.196.9/limerick/jammy/iot-limerick-kria-classic-desktop-2204-x07-20230302-63.img.xz

Output

***********************************************************

* Starting testflinger setup phase on xilinx-kv260-c32317 *

***********************************************************

Cleaning up container if it exists...
Error response from daemon: No such container: xilinx-kv260-c32317

***************************************************************

* Starting testflinger provision phase on xilinx-kv260-c32317 *

***************************************************************

2024-08-29 07:37:35,761 xilinx-kv260-c32317 INFO: DEVICE CONNECTOR: BEGIN provision
2024-08-29 07:37:35,761 xilinx-kv260-c32317 INFO: DEVICE CONNECTOR: Provisioning device

2024-08-29 07:37:48,032 xilinx-kv260-c32317 INFO: DEVICE CONNECTOR: Downloading test image from http://10.102.196.9/limerick/jammy/iot-limerick-kria-classic-desktop-2204-x07-20230302-63.img.xz
2024-08-29 07:38:10,700 xilinx-kv260-c32317 INFO: DEVICE CONNECTOR: Flashing Test image iot-limerick-kria-classic-desktop-2204-x07-20230302-63.img.xz on /dev/sda
2024-08-29 07:39:46,553 xilinx-kv260-c32317 ERROR: DEVICE CONNECTOR: Error connecting to serial logging server
2024-08-29 07:42:26,296 xilinx-kv260-c32317 ERROR: DEVICE CONNECTOR: Error connecting to serial logging server
2024-08-29 07:45:06,040 xilinx-kv260-c32317 ERROR: DEVICE CONNECTOR: Error connecting to serial logging server
2024-08-29 07:47:45,784 xilinx-kv260-c32317 ERROR: DEVICE CONNECTOR: Error connecting to serial logging server
Traceback (most recent call last):
  File "/srv/testflinger-agent/xilinx-kv260-c32317/env/bin/testflinger-device-connector", line 8, in <module>
    sys.exit(main())
  File "/srv/testflinger-agent/xilinx-kv260-c32317/env/lib/python3.10/site-packages/testflinger_device_connectors/cmd.py", line 83, in main
    sys.exit(func(args))
  File "/srv/testflinger-agent/xilinx-kv260-c32317/env/lib/python3.10/site-packages/testflinger_device_connectors/devices/__init__.py", line 321, in wrapper
    return func(*args, **kwargs)
  File "/srv/testflinger-agent/xilinx-kv260-c32317/env/lib/python3.10/site-packages/testflinger_device_connectors/devices/muxpi/__init__.py", line 52, in provision
    raise e
  File "/srv/testflinger-agent/xilinx-kv260-c32317/env/lib/python3.10/site-packages/testflinger_device_connectors/devices/muxpi/__init__.py", line 50, in provision
    device.provision()
  File "/srv/testflinger-agent/xilinx-kv260-c32317/env/lib/python3.10/site-packages/testflinger_device_connectors/devices/muxpi/muxpi.py", line 248, in provision
    with self.remote_mount():
  File "/usr/lib/python3.10/contextlib.py", line 135, in __enter__
    return next(self.gen)
  File "/srv/testflinger-agent/xilinx-kv260-c32317/env/lib/python3.10/site-packages/testflinger_device_connectors/devices/muxpi/muxpi.py", line 361, in remote_mount
    mount_list = self._get_part_labels()
  File "/srv/testflinger-agent/xilinx-kv260-c32317/env/lib/python3.10/site-packages/testflinger_device_connectors/devices/muxpi/muxpi.py", line 351, in _get_part_labels
    lsblk_json = json.loads(lsblk_data.decode())
  File "/usr/lib/python3.10/json/__init__.py", line 346, in loads
    return _default_decoder.decode(s)
  File "/usr/lib/python3.10/json/decoder.py", line 337, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/usr/lib/python3.10/json/decoder.py", line 355, in raw_decode
    raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

*************************************************************

* Starting testflinger cleanup phase on xilinx-kv260-c32317 *

*************************************************************
Cleaning up container if it exists...
Error response from daemon: No such container: xilinx-kv260-c32317
complete

[syncronize-issues-to-jira]

Thank you for reporting us your feedback!

The internal ticket has been created: https://warthogs.atlassian.net/browse/CERTTF-398.

This message was autogenerated

[LiaoU3]

I suspect it is caused by the string Warning: ... from the ssh command.

ubuntu@juju-1444ed-0:~/testflinger/xilinx-kv260-c34038$ ssh -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null ubuntu@10.102.239.223 "lsblk -o NAME,LABEL -J /dev/sda"
Warning: Permanently added '10.102.239.223' (ED25519) to the list of known hosts.
{
   "blockdevices": [
      {
         "name": "sda",
         "label": null
      }
   ]
}

[LiaoU3]

I suggest we could add -q to _run_control().

ubuntu@juju-1444ed-0:~$ ssh -q -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null ubuntu@10.102.239.223 "lsblk -o NAME,LABEL -J /dev/sda"
{
   "blockdevices": [
      {
         "name": "sda",
         "label": null
      }
   ]
}

[LiaoU3]

Thanks for the help from @kevinyehk , after setting LogLevel QUIET, this issue does not happened anymore.
I suggest that we should have a document to record this or make testflinger host to change the config right after it is braught up initially.

My job after modifying config

***********************************************************

* Starting testflinger setup phase on xilinx-kv260-c34038 *

***********************************************************

Cleaning up container if it exists...
Error response from daemon: No such container: xilinx-kv260-c34038

***************************************************************

* Starting testflinger provision phase on xilinx-kv260-c34038 *

***************************************************************

2024-09-04 06:06:32,736 xilinx-kv260-c34038 INFO: DEVICE CONNECTOR: BEGIN provision
2024-09-04 06:06:32,736 xilinx-kv260-c34038 INFO: DEVICE CONNECTOR: Provisioning device
2024-09-04 06:06:44,776 xilinx-kv260-c34038 INFO: DEVICE CONNECTOR: Downloading test image from https://tel-image-cache.canonical.com/oem-share/limerick/kria-22.04/classic-22.04-kr10/iot-limerick-kria-classic-desktop-2204-20240304-165.img.xz
2024-09-04 06:07:25,374 xilinx-kv260-c34038 INFO: DEVICE CONNECTOR: Flashing Test image iot-limerick-kria-classic-desktop-2204-20240304-165.img.xz on /dev/sda
2024-09-04 06:08:42,493 xilinx-kv260-c34038 ERROR: DEVICE CONNECTOR: Error connecting to serial logging server
ERROR: 2024-09-04 14:09:29 client.py:63 -- Timeout while trying to communicate with the server.
WARNING: 2024-09-04 14:09:29 __init__.py:792 -- Unable to retrieve job state.
2024-09-04 06:11:22,232 xilinx-kv260-c34038 ERROR: DEVICE CONNECTOR: Error connecting to serial logging server
2024-09-04 06:14:01,976 xilinx-kv260-c34038 ERROR: DEVICE CONNECTOR: Error connecting to serial logging server
^C
Cancel job 5dbedd8c-5188-4788-bc01-c90d18a95d14 before exiting (y)es/(N)o/(c)ontinue? c
2024-09-04 06:16:41,720 xilinx-kv260-c34038 ERROR: DEVICE CONNECTOR: Error connecting to serial logging server
2024-09-04 06:19:21,464 xilinx-kv260-c34038 ERROR: DEVICE CONNECTOR: Error connecting to serial logging server
No valid partitions found, retrying...
2024-09-04 06:21:38,975 xilinx-kv260-c34038 INFO: DEVICE CONNECTOR: Image type detected: ce-oem-iot
2024-09-04 06:21:38,975 xilinx-kv260-c34038 INFO: DEVICE CONNECTOR: Creating Test User
2024-09-04 06:21:50,501 xilinx-kv260-c34038 INFO: DEVICE CONNECTOR: Booting Test Image
2024-09-04 06:21:50,501 xilinx-kv260-c34038 INFO: DEVICE CONNECTOR: Running snmpset -c private -v1 10.102.183.60 .1.3.6.1.4.1.318.1.1.12.3.3.1.1.4.17 i 2
iso.3.6.1.4.1.318.1.1.12.3.3.1.1.4.17 = INTEGER: 2
2024-09-04 06:21:50,616 xilinx-kv260-c34038 INFO: DEVICE CONNECTOR: Running sleep 30
2024-09-04 06:22:01,208 xilinx-kv260-c34038 ERROR: DEVICE CONNECTOR: Error connecting to serial logging server
2024-09-04 06:22:20,639 xilinx-kv260-c34038 INFO: DEVICE CONNECTOR: Running snmpset -c private -v1 10.102.183.60 .1.3.6.1.4.1.318.1.1.12.3.3.1.1.4.17 i 1
iso.3.6.1.4.1.318.1.1.12.3.3.1.1.4.17 = INTEGER: 1
2024-09-04 06:22:20,754 xilinx-kv260-c34038 INFO: DEVICE CONNECTOR: Checking if test image booted.
2024-09-04 06:24:15,845 xilinx-kv260-c34038 INFO: DEVICE CONNECTOR: END provision

*************************************************************

* Starting testflinger cleanup phase on xilinx-kv260-c34038 *

*************************************************************
Cleaning up container if it exists...
Error response from daemon: No such container: xilinx-kv260-c34038
complete