Wrong output location for RecCeiver

[aderbenev]

When twistd --logfile is used, client information output generated by Transaction is shown on stdout instead of going into a log file specified for twistd. Consequently, if twistd is run as a daemon, all valuable information is muffled and does not appear in the log.

[mdavidsaver]

I though I remembered that twistd was redirecting stdout? Well I guess not. I'll look into it.

[aderbenev]

Some output is redirected, and some is not. I suppose that it's because in Transaction, output is handled with print >>fp, ... and fp=sys.stdout explicitly in Transaction.show

[mdavidsaver]

Can you try replacing

    def show(self, fp=sys.stdout):

with

    def show(self, fp=None):
        fp = fp or sys.stdout

[mdavidsaver]

Never mind my previous request. I shouldn't be using 'print' and stdout here anyway. Should be addressed by 2afcf12

[aderbenev]

Seems to be working better now, though there are two "inconveniences":

1. Logging level should be set in config for anything to appear in the log. I've set it to INFO, otherwise the "show" plugin is effectively defunct.
2. The log output is not very pretty on client connection:

$ tail -f -n 40 /var/log/recceiver.log 

2016-08-04 14:19:37-0400 [-] Log opened.
2016-08-04 14:19:37-0400 [-] twistd 12.0.0 (/usr/bin/python 2.7.3) starting up.
2016-08-04 14:19:37-0400 [-] reactor class: twisted.internet.pollreactor.PollReactor.
2016-08-04 14:19:37-0400 [-] Starting
2016-08-04 14:19:37-0400 [-] CastFactory starting on 55939
2016-08-04 14:19:37-0400 [-] Starting factory <recceiver.recast.CastFactory instance at 0x7fe6b3637dd0>
2016-08-04 14:19:37-0400 [-] CastFactory starting on 60730
2016-08-04 14:19:37-0400 [-] listening on IPv4Address(TCP, '0.0.0.0', 60730)
2016-08-04 14:19:37-0400 [-] Announcer starting on 47470
2016-08-04 14:19:37-0400 [-] Starting protocol <recceiver.announce.Announcer instance at 0x2e5f170>
2016-08-04 14:19:37-0400 [-] INFO:recceiver.announce setup Announcer

2016-08-04 14:19:37-0400 [-] set uid/gid 111/65534
2016-08-04 14:19:37-0400 [-] INFO:recceiver.processors Show processor show starting

2016-08-04 14:19:41-0400 [CastReceiver,0,10.0.153.32] INFO:recceiver.recast Open session from IPv4Address(TCP, '10.0.153.32', 44840)

2016-08-04 14:19:41-0400 [CastReceiver,0,10.0.153.32] INFO:recceiver.recast # From 10.0.153.32:44840

2016-08-04 14:19:41-0400 [CastReceiver,0,10.0.153.32] INFO:recceiver.recast  epicsEnvSet("PWD","/home/aderbenev/src/casttest/iocBoot/ioccasttest")

2016-08-04 14:19:41-0400 [CastReceiver,0,10.0.153.32] INFO:recceiver.recast  epicsEnvSet("HOSTNAME","sandbox")

2016-08-04 14:19:41-0400 [CastReceiver,0,10.0.153.32] INFO:recceiver.recast  epicsEnvSet("EPICS_VERSION","EPICS 3.14.12.3-10~bpo70+1")

2016-08-04 14:19:41-0400 [CastReceiver,0,10.0.153.32] INFO:recceiver.recast  record(ao, "TST:Setting-SP") {

2016-08-04 14:19:41-0400 [CastReceiver,0,10.0.153.32] INFO:recceiver.recast  }

2016-08-04 14:19:41-0400 [CastReceiver,0,10.0.153.32] INFO:recceiver.recast  record(mbbi, "TST:State-Sts") {

2016-08-04 14:19:41-0400 [CastReceiver,0,10.0.153.32] INFO:recceiver.recast  }

2016-08-04 14:19:41-0400 [CastReceiver,0,10.0.153.32] INFO:recceiver.recast # End

Logging prefix impedes output readability.

[mdavidsaver]

As the standard logging module is used now, would config w/ https://docs.python.org/2.7/library/logging.config.html give you sufficient control? If so, do you have a preference for json and dictConfig() or fileConfig()?

[aderbenev]

As far as I get it, control over the logging module output can be already obtained by setting the appropriate option. I just put that in .conf:

logformat = %%(levelname)s:%%(name)s %%(message)s

it goes in application.py and voila. However, it only gives control over the second part of the output string. Everything before the %(levelname) comes from somewhere else.

Anyways, given that globally squelching the output is not a solution, I don't think any logging format reconfiguration will help here. I'd suggest it's up to the "show" plugin to consolidate output and write it into the log at once instead of printing every line as a separate log message.