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

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].

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:
http://gerrit.ovirt.org/#/c/9037/

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.

(In reply to comment #5)

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

Dan ?

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).

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?

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.

Hence moving CLOSE UPSTREAM

my mistake ... moving to CLOSED WONTFIX