Project

General

Profile

Bug #38548

ceph-volume prints errors to stdout with --format json

Added by Jan Fajerski 7 months ago. Updated about 1 month ago.

Status:
Resolved
Priority:
Normal
Assignee:
-
Target version:
-
Start date:
03/01/2019
Due date:
% Done:

0%

Source:
Tags:
Backport:
nautilus, mimic, luminous
Regression:
No
Severity:
2 - major
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:

Description

When requesting json output from ceph volume errors (and maybe other messages) are printed to stdout. this results in tools parsing this output to see invalid json.

This was observed with the inventory subcommand, but I assume other subcommands show the same behaviour.

Example output:

 % ceph-volume inventory --format json 2>/dev/null 
--> Falling back to /tmp/ for logging. Can't use /var/log/ceph/ceph-volume.log
--> [Errno 13] Permission denied: '/var/log/ceph/ceph-volume.log'
 stderr: blkid: error: /dev/mapper/cryptswap: Permission denied
 stderr: blkid: error: /dev/mapper/cryptroot: Permission denied
 stderr: blkid: error: /dev/sda: Permission denied
 stderr: blkid: error: /dev/sda2: Permission denied
 stderr: blkid: error: /dev/sda3: Permission denied
 stderr: blkid: error: /dev/sda1: Permission denied
[{"path": "/dev/mapper/cryptroot", "sys_api": {"removable": "0", "ro": "0", "vendor": "", "model": "", "rev": "", "sas_address": "", "sas_device_handle": "", "sectors": 0, "size": 494403919360.0, "support_discard": "", "partitions": {}, "rotational": "0", "nr_requests": "128", "scheduler_mode": "", "sectorsize": "512", "human_readable_size": "460.45 GB", "path": "/dev/mapper/cryptroot", "locked": 1}, "available": false, "rejected_reasons": ["locked"], "lvs": []}, {"path": "/dev/mapper/cryptswap", "sys_api": {"removable": "0", "ro": "0", "vendor": "", "model": "", "rev": "", "sas_address": "", "sas_device_handle": "", "sectors": 0, "size": 17177058816.0, "support_discard": "", "partitions": {}, "rotational": "0", "nr_requests": "128", "scheduler_mode": "", "sectorsize": "512", "human_readable_size": "16.00 GB", "path": "/dev/mapper/cryptswap", "locked": 1}, "available": false, "rejected_reasons": ["locked"], "lvs": []}, {"path": "/dev/sda", "sys_api": {"removable": "0", "ro": "0", "vendor": "ATA", "model": "SK hynix SC311 S", "rev": "0P10", "sas_address": "", "sas_device_handle": "", "sectors": 0, "size": 512110190592.0, "support_discard": "", "partitions": {"sda2": {"start": "1024000", "sectors": "965636751", "sectorsize": 512, "size": "460.45 GB", "holders": ["dm-0"]}, "sda3": {"start": "966662144", "sectors": "33553039", "sectorsize": 512, "size": "16.00 GB", "holders": ["dm-1"]}, "sda1": {"start": "2048", "sectors": "1021952", "sectorsize": 512, "size": "499.00 MB", "holders": []}}, "rotational": "0", "nr_requests": "64", "scheduler_mode": "mq-deadline", "sectorsize": "512", "human_readable_size": "476.94 GB", "path": "/dev/sda", "locked": 1}, "available": false, "rejected_reasons": ["locked"], "lvs": []}]


Related issues

Copied to ceph-volume - Backport #41137: nautilus: ceph-volume prints errors to stdout with --format json Resolved
Copied to ceph-volume - Backport #41138: mimic: ceph-volume prints errors to stdout with --format json Resolved
Copied to ceph-volume - Backport #41139: luminous: ceph-volume prints errors to stdout with --format json Resolved
Copied to ceph-volume - Bug #41158: ceph-volume prints log messages to stdout Resolved 03/01/2019

History

#1 Updated by Jan Fajerski 7 months ago

  • Severity changed from 3 - minor to 2 - major

#2 Updated by Jan Fajerski 7 months ago

I believe this can be easily fixed by something like https://github.com/jan--f/ceph/tree/c-v-console-logging-to-stderr.

This has a lot of tests failing. Its not hard to fix them but I'm afraid I'm overlooking the reason why everything is currently printed to stdout. Was this just an oversiight or is there a somehting behind it?

#5 Updated by Nathan Cutler 5 months ago

  • Status changed from New to Need Review
  • Pull request ID set to 27675

#6 Updated by Sebastian Wagner 5 months ago

  • Backport set to nautilus

#7 Updated by Jan Fajerski about 1 month ago

  • Status changed from Need Review to Pending Backport
  • Backport changed from nautilus to nautilus, mimic, luminous

#8 Updated by Jan Fajerski about 1 month ago

  • Copied to Backport #41137: nautilus: ceph-volume prints errors to stdout with --format json added

#9 Updated by Jan Fajerski about 1 month ago

  • Copied to Backport #41138: mimic: ceph-volume prints errors to stdout with --format json added

#10 Updated by Jan Fajerski about 1 month ago

  • Copied to Backport #41139: luminous: ceph-volume prints errors to stdout with --format json added

#11 Updated by Guillaume Abrioux about 1 month ago

It seems the mentioned backports aren't enough, using:

ceph version 14.2.2-298-g0bdfdc6 (0bdfdc6b5433736bd11c321ecfa559f3b30f9187) nautilus (stable)

which contains this patch, I'm still seeing this behavior:

[root@osd1 /]# ceph-volume simple scan /dev/sda1 --stdout 2>/dev/null
Running command: /usr/sbin/cryptsetup status /dev/sda1
Running command: /bin/mount -v /dev/sda1 /tmp/tmp_NrdoM
stdout: mount: /dev/sda1 mounted on /tmp/tmp_NrdoM.
Running command: /bin/umount -v /tmp/tmp_NrdoM {
"active": "ok",
"ceph_fsid": "f3ea8c89-3b32-4abd-8aa9-07d1e6319e3b",
"cluster_name": "ceph",
"data": {
"path": "/dev/sda1",
"uuid": "de0465d1-b00b-4bd6-b1da-92e8f6cf0aef"
},
"fsid": "de0465d1-b00b-4bd6-b1da-92e8f6cf0aef",
"journal": {
"path": "/dev/sdc1",
"uuid": "b8e4707c-c28a-45fb-913f-6680a5f3b2d4"
},
"journal_uuid": "b8e4707c-c28a-45fb-913f-6680a5f3b2d4",
"keyring": "AQDSiUld6XdXGxAAksb27KOAv5/byZ9ybu8J9w==",
"magic": "ceph osd volume v026",
"none": "",
"ready": "ready",
"require_osd_release": 14,
"type": "filestore",
"whoami": 10
}
[root@osd1 /]#

#12 Updated by Alfredo Deza about 1 month ago

This is going to be a bit more involved... this function is missing the stderr default:

def write(msg):
    return _Write().raw(msg)

Which is what process.run use to spit out "Running command: ..."

Additionally, in process.py there is a 'log_descriptors()' function which allows ceph-volume to log output as it receives it asynchronously. It maps the stdout and stderr in how they come from the command output. It does this because we use different terminal coloring for stderr (yellow) than stdout (blue I think).

From looking at how this is implemented, I can't say what an easy fix would be to change that function

#13 Updated by Jan Fajerski about 1 month ago

Right we should probably never log anything to stdout. I didn't consider this on the original patch thinking terminal.write might be used for some legitimate printing of output, but turns out its only used by process.py.

I'll open another tracker ticket to track this properly.

#14 Updated by Jan Fajerski about 1 month ago

  • Copied to Bug #41158: ceph-volume prints log messages to stdout added

#15 Updated by Jan Fajerski about 1 month ago

  • Status changed from Pending Backport to Resolved

Also available in: Atom PDF