Bug 868663 - 3.1.z - vdsm: logs for forceIScsiScan are not in correct format
3.1.z - vdsm: logs for forceIScsiScan are not in correct format
Product: Red Hat Enterprise Linux 6
Classification: Red Hat
Component: vdsm (Show other bugs)
x86_64 Linux
medium Severity medium
: rc
: ---
Assigned To: Yaniv Bronhaim
: ZStream
Depends On:
  Show dependency treegraph
Reported: 2012-10-21 10:31 EDT by Dafna Ron
Modified: 2014-07-01 08:03 EDT (History)
9 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Last Closed: 2012-12-16 11:31:13 EST
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---
ybronhei: needinfo+

Attachments (Terms of Use)
log (441.57 KB, application/x-xz)
2012-10-21 10:31 EDT, Dafna Ron
no flags Details

  None (edit)
Description Dafna Ron 2012-10-21 10:31:37 EDT
Created attachment 630887 [details]

Description of problem:

MainProcess|Thread-198772::DEBUG::2012-10-21 15:57:14,750::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host2/scan' (cwd None)
MainProcess|Thread-198772::DEBUG::2012-10-21 15:57:15,755::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host52/scan' (cwd None)
MainProcess|Thread-198772::ERROR::2012-10-21 15:57:15,759::supervdsmServer::66::SuperVdsm.ServerCallback::(wrapper) Error in forceIScsiScan

it should be Thread: LEVEL. 

Version-Release number of selected component (if applicable):


How reproducible:


Steps to Reproduce:
1. run disconnectStorageServer
Actual results:

the vdsm logs for forceIScsiScan are not ordered like the rest of the threads in vdsm logs

Expected results:

forceIScsiScan should be the same as other commands in the vdsm log

Additional info: log attached
Comment 2 Saggi Mizrahi 2012-11-04 12:33:34 EST
It's part of the many things I fixed http://gerrit.ovirt.org/#/c/8172/

I noticed it straight away.

If only someone reviewed my patches
Comment 3 Yaniv Bronhaim 2012-11-05 03:34:31 EST
Saggi: I don't understand how your patch helps to that issue. It is just omit the use in log in forceIScsiScan (so it helps only once)

The issue here is that sometimes the log prints 'MainProcess|Thread-[No]' as threadName instead of only Thread-[No].
Comment 4 Yaniv Bronhaim 2012-11-05 10:11:15 EST
Apparently this is part of multiprossing.manager implementation:
check multiprocessing/managers.py line 740:
  if threading.current_thread().name != 'MainThread':                     
       name += '|' + threading.current_thread().name 

This patch is changing the name back to what we like:
Comment 5 Yaniv Bronhaim 2012-11-26 07:15:54 EST
This patch hasn't merged to upstream because of its complexity (too many string games in each print to log), The reason for this issue is the use of multiprocessing package. It changes the threadName value and the logger uses the modified name to print the record.

There are some solutions that I can do here:
1. Modifying the threadName back to Thread-[No] as my current patch does, but it can cause bugs in multiprocessing package and includes too many string games that can be expensive.

2. Derive functions from multiprocessing that modify threadName, also can cause bugs in other part of multiprocessing package that based on this threadName modification.

3. Changing MainProcess name to SVDSM so that we could use this "feature" to know if the thread is running as part of svdsm logic or vdsm logic. I'm not sure if it is really useful, but it might help to distinguish the location of an error report.

After checking solutions 1 and 2, I think that 3 is the win-win solution here and the log can look like that:

Thread-12::DEBUG::2012-11-26 14:27:48,629::misc::1054::SamplingMethod::(__call__) Returning last result

SVDSM|Thread-12::DEBUG::2012-11-26 14:27:48,631::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host0/scan' (cwd None)

SVDSM|Thread-12::DEBUG::2012-11-26 14:27:49,636::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host1/scan' (cwd None)

SVDSM|Thread-12::DEBUG::2012-11-26 14:27:50,644::iscsi::388::Storage.ISCSI::(forceIScsiScan) Performing SCSI scan, this will take up to 30 seconds

Thread-12::DEBUG::2012-11-26 14:27:52,647::misc::83::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /sbin/multipath' (cwd None)

That way you get figure if the error is part of svdsm logic flow or externally to it.
Comment 8 Barak 2012-11-27 06:09:54 EST
(In reply to comment #5)

Option #3 above looks like the best solution to me.

Dan ?
Comment 9 Dan Kenigsberg 2012-11-27 08:05:15 EST
I do not mind option #3 at all. From my pov, keeping "MainProcess|" is as good. Upstream I've suggested other ideas to solve the issue (change the format string to include threadName-without-process).
Comment 10 Yaniv Bronhaim 2012-12-04 08:40:21 EST
I can replace threadName with vdsmThreadName and modify it for each loggerAdapter. For instance, for main vdsm log I'll put threading.current_thread().name as it is right now, and for super vdsm I'll replace it with 'SVDSM' as we mentioned. But still it doesn't help, the log prints happen in vdsm scope (not in supervdsm), and the threadName is modified for the vdsm thread, so we need to find a solution that replace the use of current_thread().name with something that isn't rely on this name.

Do you have suggestions for that?
I thought about adding to threading package vdsmThreadName attribute and use that. This attribute will hold unique number for each thread as current_thread().name does now, but again.. it sounds too much for this issue.

Are we sure we want to change the current printing?
Comment 11 Barak 2012-12-16 11:31:13 EST
The suggested patch above was rejected upstream, and most people do not see it as a bug.
Some even think this is good to distinct the the logs of SuperVdsm.

Comment 12 Barak 2012-12-16 13:26:18 EST
my mistake ... moving to CLOSED WONTFIX

Note You need to log in before you can comment on or make changes to this bug.