On Jun 24, 2012, at 10:47 AM, Daniel Gonzalez wrote:
> (I am not sure what the term is for the web2py "dispatch queue")
>
> Every 10 seconds my webpage is performing a JSNORPC request. Inspecting the
> network with ngrep shows exactly that: one request every 10 seconds.
>
> This is the service being requested (in
> applications/portlet/controllers/default.py)
>
> @service.jsonrpc
> def get_cdr_page(pars_json):
> get_module_log().info("pars_json='%s' now=%s" % (pars_json, request.now))
> return []
>
> But my logfile is showing a very strange situtation:
>
> 2012-06-24 19:34:19,464 - Thread-3 - __restricted__ - INFO
> - pars_json='{"page":0}' now=2012-06-24 19:34:19.352900
> 2012-06-24 19:34:29,361 - Thread-4 - __restricted__ - INFO
> - pars_json='{"page":0}' now=2012-06-24 19:34:29.354196
> 2012-06-24 19:34:29,361 - Thread-4 - __restricted__ - INFO
> - pars_json='{"page":0}' now=2012-06-24 19:34:29.354196
> 2012-06-24 19:34:39,362 - Thread-5 - __restricted__ - INFO
> - pars_json='{"page":0}' now=2012-06-24 19:34:39.355891
> 2012-06-24 19:34:39,362 - Thread-5 - __restricted__ - INFO
> - pars_json='{"page":0}' now=2012-06-24 19:34:39.355891
> 2012-06-24 19:34:39,362 - Thread-5 - __restricted__ - INFO
> - pars_json='{"page":0}' now=2012-06-24 19:34:39.355891
> 2012-06-24 19:34:49,364 - Thread-6 - __restricted__ - INFO
> - pars_json='{"page":0}' now=2012-06-24 19:34:49.357771
> 2012-06-24 19:34:49,364 - Thread-6 - __restricted__ - INFO
> - pars_json='{"page":0}' now=2012-06-24 19:34:49.357771
> 2012-06-24 19:34:49,364 - Thread-6 - __restricted__ - INFO
> - pars_json='{"page":0}' now=2012-06-24 19:34:49.357771
> 2012-06-24 19:34:49,364 - Thread-6 - __restricted__ - INFO
> - pars_json='{"page":0}' now=2012-06-24 19:34:49.357771
>
> As I understand this log, web2py is creating a different thread each time
> that a request is received. This is as expected.
> What I do not understand, is that it seems that the code in my JSONRPC
> function seems to be executed multiple times for each request.
> Specifically, the first request executes the code once, the second request
> (10 seconds later) exectues the code twice, the thirds request (again 10
> seconds later) executes the code three times, and so on.
>
> I am completely puzzled. What does this mean?
>
I love this kind of bug, one where you'd be hard-pressed to get the result by
deliberate programming, but the bug seems to manage it with no effort
whatsoever.
Suggestion for narrowing the scope of the problem: add a second log call
(important; don't extend the existing one) that prints a high-resolution
timestamp. time.time() ought to suffice, if you print enough of its digits.
My immediate suspicion is the log logic itself, and I'm wondering whether the
multiple log entries will show the same timestamp, and whether the two calls
will show up as aabb or abab.
--
