search

shawnanastasio / libkvmchan

An implementation of the Xen vchan API on KVM
Other
10 stars 4 forks source link

libkvmchan_read fails to read all the text from stdout/stdin? #23

Closed nrgaway closed 4 years ago

nrgaway commented 4 years ago

When qrexec-client-vm dom0 qubes.SyncAppMenus /etc/qubes-rpc/qubes.GetAppmenus is started on the VM, the host RPC script qubes-SyncAppMenus fails to read all the text expected to be returned by the qubes.GetAppmenus RPC script located on the VM due to libkvmchan_read returning -1 after reading approximately 131,027 bytes of an expected 853,618 and 8,125 lines with some empty lines. It may be possible that the buffer is empty at times as the stdout is generated by a script.

Is it possible libcvmchan_read is returning early if buffer is empty while script is still processing or is there a way to determine what the error is?

VM qubes.GetAppmenus RPC script

find "${apps_dirs[@]}" -name '*.desktop' -print0 2>/dev/null | \
         xargs -0 awk '
         BEGINFILE { if (ERRNO) nextfile; entry="" }
         /^\[/ { if (tolower($0) != "\[desktop entry\]") nextfile }·
         /^Exec *=/ { entry = entry FILENAME ":Exec=qubes-desktop-run " FILENAME "\n"; next }
         /^NoDisplay *= *true$/ { entry=""; nextfile }
         /=/ { entry = entry FILENAME ":" $0 "\n" }
         ENDFILE { print entry }
         ' 2> /dev/null

Partial Log

Note that read_vchan_all calls libvchan_read(vchan, data+pos, size-pos);

06:04:31 HOST qrexec-policy-daemon[1525770]: 2020-09-19 06:04:31.455 qrexec-client[1525770]: remote.c:65:handle_remote_data: handle_remote_data: while loop
06:04:31 HOST qrexec-policy-daemon[1525770]: 2020-09-19 06:04:31.455 qrexec-client[1525770]: txrx-vchan.c:76:read_vchan_all: read_vchan_all: pos=0, size=65536
06:04:31 HOST qrexec-policy-daemon[1525770]: 2020-09-19 06:04:31.455 qrexec-client[1525770]: txrx-vchan.c:79:read_vchan_all: read_vchan_all: while_loop: pos=0, ret=65536, size=65536
06:04:31 HOST qrexec-policy-daemon[1525770]: 2020-09-19 06:04:31.455 qrexec-client[1525770]: remote.c:65:handle_remote_data: handle_remote_data: while loop
06:04:31 HOST qrexec-policy-daemon[1525770]: 2020-09-19 06:04:31.455 qrexec-client[1525770]: txrx-vchan.c:76:read_vchan_all: read_vchan_all: pos=0, size=65491
06:04:31 HOST qrexec-policy-daemon[1525770]: 2020-09-19 06:04:31.455 qrexec-client[1525770]: txrx-vchan.c:79:read_vchan_all: read_vchan_all: while_loop: pos=0, ret=65490, size=65491
06:04:31 HOST qrexec-policy-daemon[1525770]: 2020-09-19 06:04:31.455 qrexec-client[1525770]: txrx-vchan.c:79:read_vchan_all: read_vchan_all: while_loop: pos=65490, ret=1, size=65491
06:04:40 HOST qrexec-policy-daemon[1525770]: 2020-09-19 06:04:40.967 qrexec-client[1525770]: remote.c:65:handle_remote_data: handle_remote_data: while loop
06:04:40 HOST qrexec-policy-daemon[1525770]: 2020-09-19 06:04:40.967 qrexec-client[1525770]: txrx-vchan.c:76:read_vchan_all: read_vchan_all: pos=0, size=65536
06:04:40 HOST qrexec-policy-daemon[1525770]: 2020-09-19 06:04:40.967 qrexec-client[1525770]: txrx-vchan.c:79:read_vchan_all: read_vchan_all: while_loop: pos=0, ret=-1, size=65536
06:04:40 HOST qrexec-policy-daemon[1525770]: 2020-09-19 06:04:40.967 qrexec-client[1525770]: txrx-vchan.c:81:read_vchan_all: read_vchan_all: ret < 0, ret=-1
06:04:40 HOST qrexec-policy-daemon[1525770]: 2020-09-19 06:04:40.967 qrexec-client[1525770]: remote.c:76:handle_remote_data: handle_remote_data: !read_vchan_all
06:04:40 HOST qrexec-policy-daemon[1525770]: 2020-09-19 06:04:40.967 qrexec-client[1525770]: process_io.c:36:handle_vchan_error: Error while vchan read, exiting
shawnanastasio commented 4 years ago

Could you add a printf here to see what code ringbuf_sec_read_stream is actually returning? That could help narrow down which error path is being hit

nrgaway commented 4 years ago

Sure, it returns code 2.

19:45:50 HOST qrexec-policy-daemon[210786]: qrexec: qubes.SyncAppMenus+: fc32 -> @adminvm: allowed to @adminvm
19:45:50 HOST qrexec-policy-daemon[212168]: 2020-09-22 19:45:50.876 qrexec-client[212168]: qrexec-client.c:611:main: client_init: Connecting to 6, port=513, timeout=60
19:45:50 HOST kvmchand[210767]: [INFO] daemon/localhandler.c:620: Client connected! fd: 12
19:45:50 HOST kvmchand[210757]: [WARN] daemon/connections.c:287: Tried to connect to non-existent vchan at dom 6 port 513
19:45:50 HOST kvmchand[210757]: [INFO] daemon/connections.c:118: vchan_init called! server_dom: 6, client_dom: 0, port 513, read_min: 65536, write_min: 65536
19:45:50 HOST kvmchand[210759]: [INFO] daemon/libvirt.c:262: About to attach ivshmem device at /tmp/kvmchand/ivshmem_socket, index 5
19:45:50 HOST kvmchand[210763]: [INFO] daemon/ivshmem.c:534: Got connection from PID: 212062
19:45:55 HOST qrexec-policy-daemon[212168]: 2020-09-22 19:45:55.880 qrexec-client[212168]: qrexec-client.c:630:main: data_vchan connected
19:45:55 HOST qrexec-policy-daemon[212168]: 2020-09-22 19:45:55.880 qrexec-client[212168]: txrx-vchan.c:76:read_vchan_all: read_vchan_all: pos=0, size=8
19:45:55 HOST qrexec-policy-daemon[212168]: 2020-09-22 19:45:55.880 qrexec-client[212168]: txrx-vchan.c:79:read_vchan_all: read_vchan_all: while_loop: pos=0, ret=8, size=8
19:45:55 HOST qrexec-policy-daemon[212168]: 2020-09-22 19:45:55.880 qrexec-client[212168]: txrx-vchan.c:76:read_vchan_all: read_vchan_all: pos=0, size=4
19:45:55 HOST qrexec-policy-daemon[212168]: 2020-09-22 19:45:55.880 qrexec-client[212168]: txrx-vchan.c:79:read_vchan_all: read_vchan_all: while_loop: pos=0, ret=4, size=4
19:45:55 HOST qrexec-policy-daemon[212168]: 2020-09-22 19:45:55.880 qrexec-client[212168]: qrexec-client.c:632:main: data_protocol_version: 3
19:45:55 HOST qrexec-policy-daemon[212168]: 2020-09-22 19:45:55.880 qrexec-client[212168]: qrexec-client.c:635:main: prepare_ret: 0
19:45:55 HOST qrexec-policy-daemon[212168]: 2020-09-22 19:45:55.880 qrexec-client[212168]: qrexec-client.c:638:main: select_loop...
19:45:56 HOST qrexec-policy-daemon[212168]: 2020-09-22 19:45:56.380 qrexec-client[212168]: remote.c:65:handle_remote_data: handle_remote_data: while loop
19:45:56 HOST qrexec-policy-daemon[212168]: 2020-09-22 19:45:56.380 qrexec-client[212168]: txrx-vchan.c:76:read_vchan_all: read_vchan_all: pos=0, size=65536
19:45:56 HOST qrexec-policy-daemon[212168]: 2020-09-22 19:45:56.380 qrexec-client[212168]: txrx-vchan.c:79:read_vchan_all: read_vchan_all: while_loop: pos=0, ret=65536, size=65536
19:45:56 HOST qrexec-policy-daemon[212168]: 2020-09-22 19:45:56.380 qrexec-client[212168]: remote.c:65:handle_remote_data: handle_remote_data: while loop
19:45:56 HOST qrexec-policy-daemon[212168]: 2020-09-22 19:45:56.380 qrexec-client[212168]: txrx-vchan.c:76:read_vchan_all: read_vchan_all: pos=0, size=65491
19:45:56 HOST qrexec-policy-daemon[212168]: 2020-09-22 19:45:56.380 qrexec-client[212168]: txrx-vchan.c:79:read_vchan_all: read_vchan_all: while_loop: pos=0, ret=65490, size=65491
19:45:56 HOST qrexec-policy-daemon[212168]: 2020-09-22 19:45:56.380 qrexec-client[212168]: txrx-vchan.c:79:read_vchan_all: read_vchan_all: while_loop: pos=65490, ret=1, size=65491
19:46:05 HOST qrexec-policy-daemon[212168]: 2020-09-22 19:46:05.892 qrexec-client[212168]: remote.c:65:handle_remote_data: handle_remote_data: while loop
19:46:05 HOST qrexec-policy-daemon[212168]: 2020-09-22 19:46:05.892 qrexec-client[212168]: txrx-vchan.c:76:read_vchan_all: read_vchan_all: pos=0, size=65536

# 'libkvmchan_read' return code
19:46:05 HOST qrexec-policy-daemon[212168]: [INFO] library.c:590: libkvmchan_read.CODE: 2

19:46:05 HOST qrexec-policy-daemon[212168]: 2020-09-22 19:46:05.892 qrexec-client[212168]: txrx-vchan.c:79:read_vchan_all: read_vchan_all: while_loop: pos=0, ret=-1, size=65536
19:46:05 HOST qrexec-policy-daemon[212168]: 2020-09-22 19:46:05.892 qrexec-client[212168]: txrx-vchan.c:81:read_vchan_all: read_vchan_all: ret < 0, ret=-1
19:46:05 HOST qrexec-policy-daemon[212168]: 2020-09-22 19:46:05.892 qrexec-client[212168]: remote.c:76:handle_remote_data: handle_remote_data: !read_vchan_all
19:46:05 HOST qrexec-policy-daemon[212168]: 2020-09-22 19:46:05.892 qrexec-client[212168]: process_io.c:36:handle_vchan_error: Error while vchan read, exiting
19:46:05 HOST kvmchand[210767]: [INFO] daemon/localhandler.c:628: Client disconnected! fd: 12
19:46:05 HOST qrexec-policy-daemon[210786]: qrexec: qubes.SyncAppMenus: fc32 -> dom0: error while executing: qrexec-client failed: ['/usr/lib/qubes/qrexec-client', '-d', '@adminvm', '-c', 'SOCKET10,fc32,6', '-E', 'QUBESRPC qubes.SyncAppMenus+ fc32 keyword adminvm']
19:46:05 HOST qubes.SyncAppMenus+-fc32[212203]: fc32: Updating gnome-system-monitor-kde
19:46:05 HOST qubes.SyncAppMenus+-fc32[212203]: fc32: Get icon: vm=<qubesadmin.vm.QubesVM object at 0x7f6d7ad94730>, icon=org.gnome.SystemMonitor
19:46:05 HOST qrexec-policy-daemon[212201]: fc32: Updating gnome-system-monitor-kde
19:46:05 HOST qrexec-policy-daemon[212201]: fc32: Get icon: vm=<qubesadmin.vm.QubesVM object at 0x7f6d7ad94730>, icon=org.gnome.SystemMonitor
19:46:05 HOST kvmchand[210767]: [INFO] daemon/localhandler.c:620: Client connected! fd: 12
19:46:05 HOST kvmchand[210757]: [INFO] daemon/connections.c:118: vchan_init called! server_dom: 0, client_dom: 6, port 514, read_min: 65536, write_min: 65536
19:46:05 HOST kvmchand[210759]: [INFO] daemon/libvirt.c:262: About to attach ivshmem device at /tmp/kvmchand/ivshmem_socket, index 6
19:46:05 HOST kvmchand[210763]: [INFO] daemon/ivshmem.c:534: Got connection from PID: 212062
19:46:12 HOST kvmchand[210767]: [INFO] daemon/localhandler.c:628: Client disconnected! fd: 12
19:46:12 HOST qrexec-policy-daemon[212201]: fc32: Got icon
19:46:12 HOST qubes.SyncAppMenus+-fc32[212203]: fc32: Got icon
19:46:12 HOST qrexec-policy-daemon[212201]: fc32: Updating org.gnome.clocks
19:46:12 HOST qrexec-policy-daemon[212201]: fc32: Get icon: vm=<qubesadmin.vm.QubesVM object at 0x7f6d7ad94730>, icon=org.gnome.clocks
19:46:12 HOST qubes.SyncAppMenus+-fc32[212203]: fc32: Updating org.gnome.clocks
19:46:12 HOST qubes.SyncAppMenus+-fc32[212203]: fc32: Get icon: vm=<qubesadmin.vm.QubesVM object at 0x7f6d7ad94730>, icon=org.gnome.clocks
19:46:12 HOST kvmchand[210767]: [INFO] daemon/localhandler.c:620: Client connected! fd: 12
19:46:12 HOST kvmchand[210757]: [INFO] daemon/connections.c:118: vchan_init called! server_dom: 0, client_dom: 6, port 514, read_min: 65536, write_min: 65536
19:46:12 HOST kvmchand[210759]: [INFO] daemon/libvirt.c:262: About to attach ivshmem device at /tmp/kvmchand/ivshmem_socket, index 7
19:46:12 HOST kvmchand[210763]: [INFO] daemon/ivshmem.c:534: Got connection from PID: 212062
19:46:12 HOST systemd[1]: Started Process Core Dump (PID 212248/UID 0).
19:46:12 HOST audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-coredump@0-212248-0 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
19:46:12 HOST systemd-coredump[212249]: Resource limits disable core dumping for process 212062 (qemu-system-x86).
19:46:12 HOST systemd-coredump[212249]: Process 212062 (qemu-system-x86) of user 107 dumped core.
shawnanastasio commented 4 years ago

Thanks. After carefully reviewing the code again, I spotted a completely bogus check in ringbuf_read that could result in the call failing even when there are actually enough bytes available. Fixing this revealed an off-by-one in the ringbuf free space calculation elsewhere which, funnily enough, I fixed in another one of my projects which uses the same ringbuf code but somehow forgot to fix it here too.

The good part is that neither of these bugs should have had security implications due to the strict pointer boundary checks, but it's still pretty embarrassing. In any case, I've pushed a fix in https://github.com/shawnanastasio/libkvmchan/commit/7b16b2ab302db5ba26232a866e99418ee6c99e48. Let me know if this fixes it.

nrgaway commented 4 years ago

Awesome! Patch works, read all 853,618 bytes.

Still have same coredump issue though :( Weird since there are no failures I can detect anywhere until coredump.

shawnanastasio commented 4 years ago

Awesome! Patch works, read all 853,618 bytes.

Nice! I'll close this issue then.

Still have same coredump issue though :( Weird since there are no failures I can detect anywhere until coredump.

Darn, it would have been nice if this automatically got fixed. We can continue tracking it down in #21.