Config Python 3 Guest Worker: "stdout": "log", "stderr": "log" Not Implemented?

#1

Hi All,

I’m attempting to get simple print and traceback statements to work out of a python 3 guest worker. I have set the config as such:

{
   "id": "backend",
   "type": "guest",
   "executable": "python3",
   "arguments": ["backend.py"],
   "options": {
      "workdir": "../backend",
      "watch": {
         "directories": ["../backend"],
         "action": "restart"
      },
      "stdout": "log",
      "stderr": "log"
   }
}

Is stdout and stderror implemented? I’ve found this: http://stackoverflow.com/questions/28251494/how-to-log-debug-a-crossbar-guest-worker but I don’t want to use a hack if the config can handle this for me…

I am not using any of the debug options on the ApplicationRunner as I have read posts from Tobias that they are still figuring out exactly how they are implementing the debug levels (I can’t find the link, it was on one of the two google groups)

There is this question too, very similar: https://groups.google.com/forum/#!searchin/crossbario/"stdout"$3A$20"log"/crossbario/v5dgtfWPSzE/yFG5Rf7GU5YJ

Any help is appreciated, will post here if I find the answer…

Dave

0 Likes

#2

On close inspection of the crossbar teardown terminal output, it looks like there ARE traceback and print statements that exist in the router but nothing is getting forwarded from the guest until CTRL+C’ing the crossbar process (Print statements highlighted), is this a known bug? Something blocking the stdout?

2015-04-24 16:33:53-0400 [Controller 4171] Log opened.

2015-04-24 16:33:53-0400 [Controller 4171] ==================== Crossbar.io ====================

2015-04-24 16:33:53-0400 [Controller 4171] Crossbar.io 0.10.4 starting

2015-04-24 16:33:53-0400 [Controller 4171] Running on PyPy using EPollReactor reactor

2015-04-24 16:33:53-0400 [Controller 4171] Starting from node directory /home/vbcdr/wamp/.crossbar

2015-04-24 16:33:54-0400 [Controller 4171] Starting from local configuration ‘/home/vbcdr/wamp/.crossbar/config.json’

2015-04-24 16:33:54-0400 [Controller 4171] Router created for realm ‘crossbar’

2015-04-24 16:33:54-0400 [Controller 4171] No WAMPlets detected in enviroment.

2015-04-24 16:33:54-0400 [Controller 4171] Starting Router with ID ‘wamprouter’ …

2015-04-24 16:33:54-0400 [Controller 4171] Entering reactor event loop …

2015-04-24 16:33:54-0400 [Router 4182] Log opened.

2015-04-24 16:33:56-0400 [Router 4182] Running under PyPy using EPollReactor reactor

2015-04-24 16:33:56-0400 [Router 4182] Entering event loop …

2015-04-24 16:33:56-0400 [Controller 4171] Router with ID ‘wamprouter’ and PID 4182 started

2015-04-24 16:33:56-0400 [Controller 4171] Router ‘wamprouter’: realm ‘realm1’ (named ‘realm1’) started

2015-04-24 16:33:56-0400 [Controller 4171] Router ‘wamprouter’: role ‘role1’ (named ‘authenticator’) started on realm ‘realm1’

2015-04-24 16:33:56-0400 [Controller 4171] Router ‘wamprouter’: role ‘role2’ (named ‘authorizer’) started on realm ‘realm1’

2015-04-24 16:33:56-0400 [Controller 4171] Router ‘wamprouter’: role ‘role3’ (named ‘backend’) started on realm ‘realm1’

2015-04-24 16:33:56-0400 [Controller 4171] Router ‘wamprouter’: role ‘role4’ (named ‘frontend’) started on realm ‘realm1’

2015-04-24 16:33:56-0400 [Router 4182] enabling WebSocket compression (permessage-deflate)

2015-04-24 16:33:56-0400 [Router 4182] CrossbarWampWebSocketServerFactory starting on 9000

2015-04-24 16:33:56-0400 [Controller 4171] Router ‘wamprouter’: transport ‘loopback’ started

2015-04-24 16:33:56-0400 [Router 4182] enabling WebSocket compression (permessage-deflate)

2015-04-24 16:33:56-0400 [Router 4182] Using default cipher list.

2015-04-24 16:33:56-0400 [Router 4182] Warning: OpenSSL DH modes not active - missing DH param file

2015-04-24 16:33:56-0400 [Router 4182] Ok, OpenSSL is using ECDH elliptic curve prime256v1

2015-04-24 16:33:56-0400 [Router 4182] Site (TLS) starting on 8015

2015-04-24 16:33:56-0400 [Controller 4171] Router ‘wamprouter’: transport ‘web’ started

2015-04-24 16:33:56-0400 [Controller 4171] Using guest worker executable ‘/usr/bin/python3’ (executable path detected from environment)

2015-04-24 16:33:56-0400 [Controller 4171] Starting Guest with ID ‘authenticator’ …

2015-04-24 16:33:56-0400 [Controller 4171] Guest with ID ‘authenticator’ and PID 4189 started

2015-04-24 16:33:57-0400 [Controller 4171] Guest ‘authenticator’: started

2015-04-24 16:33:57-0400 [Controller 4171] Using guest worker executable ‘/usr/bin/python3’ (executable path detected from environment)

2015-04-24 16:33:57-0400 [Controller 4171] Starting Guest with ID ‘authorizer’ …

2015-04-24 16:33:57-0400 [Controller 4171] Guest with ID ‘authorizer’ and PID 4193 started

2015-04-24 16:33:57-0400 [Controller 4171] Guest ‘authorizer’: started

2015-04-24 16:33:57-0400 [Controller 4171] Using guest worker executable ‘/usr/bin/python3’ (executable path detected from environment)

2015-04-24 16:33:57-0400 [Controller 4171] Starting Guest with ID ‘backend’ …

2015-04-24 16:33:57-0400 [Controller 4171] Guest with ID ‘backend’ and PID 4197 started

2015-04-24 16:33:57-0400 [Controller 4171] Guest ‘backend’: started

2015-04-24 16:33:57-0400 [Router 4182] onAuthenticate: JF4ILkMaZSgz8wfu/jxmwr2R5CMHuUOAxKMGLt12IHg= {}

2015-04-24 16:33:57-0400 [Router 4182] onAuthenticate: 78ST8tA9ZwV87z3Pos2dHIHFGT8xRISdfsSnxaw/334= {}

<<< THIS IS WHERE THINGS STOP UNTIL CTRL+C BELOW, IF DEBUG ENABLED SOME DEBUG MESSAGES (LOW LEVEL WAMP) WILL SCROLL AT SOME SORT OF SET INTERVAL (MAYBE EVERY 60 SECONDS? CONFIGURABLE?) >>>

^C2015-04-24 16:34:02-0400 [Controller 4171] Received SIGINT, shutting down.

2015-04-24 16:34:02-0400 [Guest 4193] Connected. Joining realm realm1 user authorUser … THIS IS A PRINT STATEMENT THAT SHOULD HAVE ALREADY SCROLLED

2015-04-24 16:34:02-0400 [Guest 4193] onLeave: CloseDetails(reason = wamp.error.no_such_procedure, message = ‘no callee registered for procedure ‘com.vbcdr.authenticate’’’)

2015-04-24 16:34:02-0400 [Guest 4189] Connected. Joining realm realm1 user authenUser …

2015-04-24 16:34:02-0400 [Guest 4189] Authentication challenge received: Challenge(method = wampcra, extra = {‘keylen’: 16, ‘challenge’: ‘{“authid”: “authenUser”, “authrole”: “authenticator”, “authmethod”: “wampcra”, “authprovider”: “static”, “session”: 784693689, “nonce”: “rgUmMYfaXm4wJvsh”, “timestamp”: “2015-04-24T20:33:57.213Z”}’, ‘salt’: ‘salt123’, ‘iterations’: 100})

2015-04-24 16:34:02-0400 [Guest 4189] 1 procedures registered.

2015-04-24 16:34:02-0400 [Guest 4189] Authenticate called: realm = ‘realm1’, authid = ‘backendUser’, details = ‘{‘transport’: {‘http_headers_received’: {‘pragma’: ‘no-cache’, ‘upgrade’: ‘WebSocket’, ‘user-agent’: ‘AutobahnPython/0.10.3’, ‘sec-websocket-key’: ‘BLO3n/hZD9ah0DVH1kcYDQ==’, ‘sec-websocket-protocol’: ‘wamp.2.json.batched,wamp.2.json’, ‘connection’: ‘Upgrade’, ‘sec-websocket-version’: ‘13’, ‘cache-control’: ‘no-cache’, ‘host’: ‘:8015’}, ‘http_headers_sent’: {}, ‘protocol’: ‘wamp.2.json.batched’, ‘type’: ‘websocket’, ‘peer’: ‘tcp4:10.15.0.1:50795’}, ‘session’: 458918901}’

2015-04-24 16:34:02-0400 [Controller 4171] sending TERM to subprocess 4182

2015-04-24 16:34:02-0400 [Controller 4171] waiting for 4182 to exit…

2015-04-24 16:34:02-0400 [Controller 4171] sending TERM to subprocess 4189

2015-04-24 16:34:02-0400 [Controller 4171] waiting for 4189 to exit…

2015-04-24 16:34:02-0400 [Controller 4171] sending TERM to subprocess 4193

2015-04-24 16:34:02-0400 [Controller 4171] waiting for 4193 to exit…

2015-04-24 16:34:02-0400 [Controller 4171] sending TERM to subprocess 4197

2015-04-24 16:34:02-0400 [Controller 4171] waiting for 4197 to exit…

2015-04-24 16:34:02-0400 [Guest 4189] Traceback (most recent call last):

2015-04-24 16:34:02-0400 [Guest 4189] File “authentication.py”, line 70, in

2015-04-24 16:34:02-0400 [Guest 4189] runner.run(MyBackendComponent)

2015-04-24 16:34:02-0400 [Guest 4189] File “/usr/local/lib/python3.4/dist-packages/autobahn/asyncio/wamp.py”, line 141, in run

2015-04-24 16:34:02-0400 [Guest 4189] loop.run_forever()

2015-04-24 16:34:02-0400 [Guest 4189] File “/usr/lib/python3.4/asyncio/base_events.py”, line 184, in run_forever

2015-04-24 16:34:02-0400 [Guest 4189] self._run_once()

2015-04-24 16:34:02-0400 [Guest 4189] File “/usr/lib/python3.4/asyncio/base_events.py”, line 799, in _run_once

2015-04-24 16:34:02-0400 [Guest 4189] event_list = self._selector.select(timeout)

2015-04-24 16:34:02-0400 [Guest 4189] File “/usr/lib/python3.4/selectors.py”, line 424, in select

2015-04-24 16:34:02-0400 [Guest 4189] fd_event_list = self._epoll.poll(timeout, max_ev)

2015-04-24 16:34:02-0400 [Guest 4189] KeyboardInterrupt

2015-04-24 16:34:02-0400 [Guest 4193] Traceback (most recent call last):

2015-04-24 16:34:02-0400 [Guest 4193] File “authorization.py”, line 61, in

2015-04-24 16:34:02-0400 [Guest 4193] runner.run(MyBackendComponent)

2015-04-24 16:34:02-0400 [Guest 4193] File “/usr/local/lib/python3.4/dist-packages/autobahn/asyncio/wamp.py”, line 141, in run

2015-04-24 16:34:02-0400 [Guest 4193] loop.run_forever()

2015-04-24 16:34:02-0400 [Guest 4193] File “/usr/lib/python3.4/asyncio/base_events.py”, line 184, in run_forever

2015-04-24 16:34:02-0400 [Guest 4193] self._run_once()

2015-04-24 16:34:02-0400 [Guest 4193] File “/usr/lib/python3.4/asyncio/base_events.py”, line 799, in _run_once

2015-04-24 16:34:02-0400 [Guest 4193] event_list = self._selector.select(timeout)

2015-04-24 16:34:02-0400 [Guest 4193] File “/usr/lib/python3.4/selectors.py”, line 424, in select

2015-04-24 16:34:02-0400 [Guest 4193] fd_event_list = self._epoll.poll(timeout, max_ev)

2015-04-24 16:34:02-0400 [Guest 4193] KeyboardInterrupt

2015-04-24 16:34:02-0400 [Router 4182] Ignoring SIGINT in worker.

2015-04-24 16:34:02-0400 [Router 4182] Received SIGTERM, shutting down.

2015-04-24 16:34:02-0400 [Router 4182] Connection to node controller lost.

2015-04-24 16:34:02-0400 [Router 4182] (TCP Port 9000 Closed)

2015-04-24 16:34:02-0400 [Router 4182] (TLS Port 8015 Closed)

2015-04-24 16:34:02-0400 [Router 4182] Main loop terminated.

2015-04-24 16:34:02-0400 [Controller 4171] Guest exited with error [Failure instance: Traceback (failure with no frames): <class ‘twisted.internet.error.ProcessTerminated’>: A process has ended with a probable error condition: process ended by signal 15.

]

2015-04-24 16:34:02-0400 [Controller 4171] Guest exited with error [Failure instance: Traceback (failure with no frames): <class ‘twisted.internet.error.ProcessTerminated’>: A process has ended with a probable error condition: process ended by signal 15.

]

2015-04-24 16:34:02-0400 [Controller 4171] Guest exited with error [Failure instance: Traceback (failure with no frames): <class ‘twisted.internet.error.ProcessTerminated’>: A process has ended with a probable error condition: process ended by signal 15.

]

2015-04-24 16:34:02-0400 [Controller 4171] Worker 4182: Process connection gone (Connection was closed cleanly.)

2015-04-24 16:34:02-0400 [Controller 4171] Main loop terminated.

``

0 Likes

#3

Opened: https://github.com/crossbario/crossbar/issues/314

0 Likes

#4

https://bugs.python.org/issue11633 and https://docs.python.org/2/using/cmdline.html#cmdoption-u are related.

If you set PYTHONUNBUFFERED=1 in your config, logging works as-expected. Perhaps crossbar should just set this env-var automagically? To immediately fix the issue described, add a config snippit like this to your guest:

"options"    : {
"env"        : {
"vars"            : {
"PYTHONUNBUFFERED": "1"
        }
}
}

Crossbar config.json required a string of “1”, it would not accept JSON Int 1

You can also add "-u" to the arguments list (instead of the env-var).

         {
"id": "backend"         ,
"type": "guest"         ,
"executable": "python3"         ,
"arguments": ["backend.py"         ],
"options"            : {
"env"               : {
"vars"                  : {
"PYTHONUNBUFFERED": "1"
               }
},
"workdir": "../backend"            ,
"stdout": "log"            ,
"stderr": "log"            ,
"watch"               : {
"directories": ["../backend"               ],
"action": "restart"
            }
}
}
0 Likes

#5

Thanks for this, it helped me.
Both ways work, I like adding the “-p”, because it makes the config simpler:

  {
     "type": "guest",
     "executable": "pyvirt/bin/python",
     "arguments": ["-u", "test.py"],
     "options": {"workdir": "../../crossbar-guest"}
  },
0 Likes

#6

duh meant “-u”

0 Likes

#7

We’ve added a note in the docs http://crossbar.io/docs/Guest-Configuration/#executable-path

···

Am Freitag, 1. Mai 2015 20:18:16 UTC+2 schrieb Dave Thomas:

https://bugs.python.org/issue11633 and https://docs.python.org/2/using/cmdline.html#cmdoption-u are related.

If you set PYTHONUNBUFFERED=1 in your config, logging works as-expected. Perhaps crossbar should just set this env-var automagically? To immediately fix the issue described, add a config snippit like this to your guest:

"options"    : {
"env"        : {
"vars"            : {
"PYTHONUNBUFFERED": "1"
        }
}
}

Crossbar config.json required a string of “1”, it would not accept JSON Int 1

You can also add "-u" to the arguments list (instead of the env-var).

         {
"id": "backend"         ,
"type": "guest"         ,
"executable": "python3"         ,
"arguments": ["backend.py"         ],
"options"            : {
"env"               : {
"vars"                  : {
"PYTHONUNBUFFERED": "1"
               }
},
"workdir": "../backend"            ,
"stdout": "log"            ,
"stderr": "log"            ,
"watch"               : {
"directories": ["../backend"               ],
"action": "restart"
            }
}
}
0 Likes