2017-05-03 13:51:30,648 INFO lifecycle - event: {"request": "757", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: filter", "path": "/xforms-server", "method": "POST"} 2017-05-03 13:51:30,648 INFO lifecycle - event: {"request": "757", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: chain", "path": "/xforms-server", "method": "POST", "wait": "0"} 2017-05-03 13:51:30,649 INFO lifecycle - event: {"request": "757", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "start: handle"} 2017-05-03 13:51:30,649 INFO ProcessorService - /xforms-server - Received request 2017-05-03 13:51:30,659 INFO lifecycle - event: {"request": "757", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "ajax with update events", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77"} 2017-05-03 13:51:30,659 INFO lifecycle - event: {"request": "757", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "before document lock", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77"} 2017-05-03 13:51:30,660 INFO lifecycle - event: {"request": "757", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "got document lock", "path": "/xforms-server", "method": "POST", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77", "wait": "1"} 2017-05-03 13:51:30,662 INFO lifecycle - event: {"request": "757", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "fr", "message": "start: process", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77", "scope": "oxf.fr.detail.process", "name": "test"} 2017-05-03 13:51:30,665 INFO lifecycle - event: {"request": "757", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "fr", "message": "end: process", "time": "2 ms"} 2017-05-03 13:51:30,666 INFO lifecycle - event: {"request": "757", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "after cacheOrStore", "document cache current size": "34", "document cache max size": "50"} 2017-05-03 13:51:30,667 INFO ProcessorService - /xforms-server - Timing: 18 2017-05-03 13:51:30,667 INFO lifecycle - event: {"request": "757", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "end: handle", "time": "19 ms"} 2017-05-03 13:51:30,667 INFO lifecycle - event: {"request": "757", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: chain", "time": "19 ms"} 2017-05-03 13:51:30,667 INFO lifecycle - event: {"request": "757", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: filter", "time": "20 ms"} 2017-05-03 13:51:30,929 INFO lifecycle - event: {"request": "758", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: filter", "path": "/xforms-server", "method": "POST"} 2017-05-03 13:51:30,929 INFO lifecycle - event: {"request": "758", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: chain", "path": "/xforms-server", "method": "POST", "wait": "0"} 2017-05-03 13:51:30,930 INFO lifecycle - event: {"request": "758", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "start: handle"} 2017-05-03 13:51:30,930 INFO ProcessorService - /xforms-server - Received request 2017-05-03 13:51:30,941 INFO lifecycle - event: {"request": "758", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "ajax with update events", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77"} 2017-05-03 13:51:30,941 INFO lifecycle - event: {"request": "758", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "before document lock", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77"} 2017-05-03 13:51:30,942 INFO lifecycle - event: {"request": "758", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "got document lock", "path": "/xforms-server", "method": "POST", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77", "wait": "0"} 2017-05-03 13:51:31,021 WARN XFormsServer - xxf:instance() - instance not found {instance id: "fr-xforms-inspector-input"} 2017-05-03 13:51:31,062 INFO lifecycle - event: {"request": "758", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "after cacheOrStore", "document cache current size": "34", "document cache max size": "50"} 2017-05-03 13:51:31,062 INFO ProcessorService - /xforms-server - Timing: 132 2017-05-03 13:51:31,062 INFO lifecycle - event: {"request": "758", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "end: handle", "time": "132 ms"} 2017-05-03 13:51:31,062 INFO lifecycle - event: {"request": "758", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: chain", "time": "133 ms"} 2017-05-03 13:51:31,062 INFO lifecycle - event: {"request": "758", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: filter", "time": "133 ms"} 2017-05-03 13:51:31,186 INFO lifecycle - event: {"request": "759", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: filter", "path": "/fr/orbeon/builder/edit/82123a4f182463064078e2ef1eab8ecc42232047", "method": "POST"} 2017-05-03 13:51:31,186 INFO lifecycle - event: {"request": "759", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: chain", "path": "/fr/orbeon/builder/edit/82123a4f182463064078e2ef1eab8ecc42232047", "method": "POST", "wait": "0"} 2017-05-03 13:51:31,186 INFO lifecycle - event: {"request": "759", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "start: handle"} 2017-05-03 13:51:31,187 INFO ProcessorService - /fr/orbeon/builder/edit/82123a4f182463064078e2ef1eab8ecc42232047 - Received request 2017-05-03 13:51:31,210 INFO lifecycle - event: {"request": "759", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "before document lock", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77"} 2017-05-03 13:51:31,211 INFO lifecycle - event: {"request": "759", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "got document lock", "path": "/fr/orbeon/builder/edit/82123a4f182463064078e2ef1eab8ecc42232047", "method": "POST", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77", "wait": "0"} 2017-05-03 13:51:31,257 INFO lifecycle - event: {"request": "759", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "after cacheOrStore", "document cache current size": "34", "document cache max size": "50"} 2017-05-03 13:51:31,258 INFO lifecycle - event: {"request": "760", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "start: handle", "path": "/fr/DatosXMLDoc/DatosXMLDoc/test", "method": "POST"} 2017-05-03 13:51:31,258 INFO ProcessorService - /fr/DatosXMLDoc/DatosXMLDoc/test - Received request 2017-05-03 13:51:31,371 INFO lifecycle - event: {"request": "760", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "new form session", "uuid": "dfe7baf6d5840ae683143c49030ace895294298b"} 2017-05-03 13:51:31,411 WARN XFormsServer - xxf:instance() - instance not found {instance id: "fr-xforms-inspector-input"} 2017-05-03 13:51:31,412 WARN XFormsServer - xxf:instance() - instance not found {instance id: ""} 2017-05-03 13:51:31,452 INFO lifecycle - event: {"request": "761", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "start: handle", "path": "/xforms-sandbox/service/zip-states_MT05", "method": "GET"} 2017-05-03 13:51:31,453 INFO ProcessorService - /xforms-sandbox/service/zip-states_MT05 - Received request 2017-05-03 13:51:31,461 INFO PageFlowControllerProcessor - not found {controller: "oxf:/apps/xforms-sandbox/page-flow.xml", method: "GET", path: "/xforms-sandbox/service/zip-states_MT05", resource: "/apps/xforms-sandbox/services/zip-states_MT05.xpl"} 2017-05-03 13:51:31,462 INFO ProcessorService - /xforms-sandbox/service/zip-states_MT05 - Timing: 10 2017-05-03 13:51:31,462 INFO lifecycle - event: {"request": "761", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "end: handle", "time": "10 ms"} 2017-05-03 13:51:31,464 ERROR XFormsServer - xforms-submit-error - xf:submission for submission id: get-itemset, error code received when submitting instance: 404 2017-05-03 13:51:31,562 INFO lifecycle - event: {"request": "760", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "after cacheOrStore", "document cache current size": "35", "document cache max size": "50"} 2017-05-03 13:51:31,594 INFO ProcessorService - /fr/DatosXMLDoc/DatosXMLDoc/test - Timing: 336 2017-05-03 13:51:31,595 INFO lifecycle - event: {"request": "760", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "end: handle", "time": "337 ms"} 2017-05-03 13:51:31,606 INFO ProcessorService - /fr/orbeon/builder/edit/82123a4f182463064078e2ef1eab8ecc42232047 - Timing: 419 2017-05-03 13:51:31,639 INFO lifecycle - event: {"request": "759", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "end: handle", "time": "452 ms"} 2017-05-03 13:51:31,639 INFO lifecycle - event: {"request": "759", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: chain", "time": "453 ms"} 2017-05-03 13:51:31,639 INFO lifecycle - event: {"request": "759", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: filter", "time": "453 ms"} 2017-05-03 13:51:32,680 INFO lifecycle - event: {"request": "762", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: filter", "path": "/xforms-server", "method": "POST"} 2017-05-03 13:51:32,681 INFO lifecycle - event: {"request": "762", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: chain", "path": "/xforms-server", "method": "POST", "wait": "0"} 2017-05-03 13:51:32,685 INFO lifecycle - event: {"request": "762", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "start: handle"} 2017-05-03 13:51:32,685 INFO ProcessorService - /xforms-server - Received request 2017-05-03 13:51:32,694 INFO lifecycle - event: {"request": "762", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "ajax with update events", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77"} 2017-05-03 13:51:32,694 INFO lifecycle - event: {"request": "762", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "before document lock", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77"} 2017-05-03 13:51:32,694 INFO lifecycle - event: {"request": "762", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "got document lock", "path": "/xforms-server", "method": "POST", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77", "wait": "0"} 2017-05-03 13:51:32,742 WARN XFormsServer - xxf:instance() - instance not found {instance id: "fr-xforms-inspector-input"} 2017-05-03 13:51:32,793 INFO lifecycle - event: {"request": "762", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "after cacheOrStore", "document cache current size": "35", "document cache max size": "50"} 2017-05-03 13:51:32,794 INFO ProcessorService - /xforms-server - Timing: 108 2017-05-03 13:51:32,794 INFO lifecycle - event: {"request": "762", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "end: handle", "time": "109 ms"} 2017-05-03 13:51:32,794 INFO lifecycle - event: {"request": "762", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: chain", "time": "113 ms"} 2017-05-03 13:51:32,795 INFO lifecycle - event: {"request": "762", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: filter", "time": "114 ms"} 2017-05-03 13:51:34,836 INFO lifecycle - event: {"request": "763", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: filter", "path": "/xforms-server", "method": "POST"} 2017-05-03 13:51:34,836 INFO lifecycle - event: {"request": "763", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: chain", "path": "/xforms-server", "method": "POST", "wait": "0"} 2017-05-03 13:51:34,837 INFO lifecycle - event: {"request": "763", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "start: handle"} 2017-05-03 13:51:34,838 INFO ProcessorService - /xforms-server - Received request 2017-05-03 13:51:34,848 INFO lifecycle - event: {"request": "763", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "ajax with update events", "uuid": "dfe7baf6d5840ae683143c49030ace895294298b"} 2017-05-03 13:51:34,848 INFO lifecycle - event: {"request": "763", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "before document lock", "uuid": "dfe7baf6d5840ae683143c49030ace895294298b"} 2017-05-03 13:51:34,848 INFO lifecycle - event: {"request": "763", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "got document lock", "path": "/xforms-server", "method": "POST", "uuid": "dfe7baf6d5840ae683143c49030ace895294298b", "wait": "0"} 2017-05-03 13:51:34,871 INFO lifecycle - event: {"request": "763", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "after cacheOrStore", "document cache current size": "35", "document cache max size": "50"} 2017-05-03 13:51:34,871 INFO ProcessorService - /xforms-server - Timing: 34 2017-05-03 13:51:34,872 INFO lifecycle - event: {"request": "763", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "end: handle", "time": "35 ms"} 2017-05-03 13:51:34,872 INFO lifecycle - event: {"request": "763", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: chain", "time": "36 ms"} 2017-05-03 13:51:34,872 INFO lifecycle - event: {"request": "763", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: filter", "time": "37 ms"} 2017-05-03 13:51:35,475 INFO lifecycle - event: {"request": "764", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: filter", "path": "/xforms-server", "method": "POST"} 2017-05-03 13:51:35,476 INFO lifecycle - event: {"request": "764", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: chain", "path": "/xforms-server", "method": "POST", "wait": "0"} 2017-05-03 13:51:35,476 INFO lifecycle - event: {"request": "764", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "start: handle"} 2017-05-03 13:51:35,476 INFO ProcessorService - /xforms-server - Received request 2017-05-03 13:51:35,483 INFO lifecycle - event: {"request": "764", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "ajax with update events", "uuid": "dfe7baf6d5840ae683143c49030ace895294298b"} 2017-05-03 13:51:35,483 INFO lifecycle - event: {"request": "764", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "before document lock", "uuid": "dfe7baf6d5840ae683143c49030ace895294298b"} 2017-05-03 13:51:35,483 INFO lifecycle - event: {"request": "764", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "got document lock", "path": "/xforms-server", "method": "POST", "uuid": "dfe7baf6d5840ae683143c49030ace895294298b", "wait": "0"} 2017-05-03 13:51:35,506 INFO lifecycle - event: {"request": "764", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "after cacheOrStore", "document cache current size": "35", "document cache max size": "50"} 2017-05-03 13:51:35,507 INFO ProcessorService - /xforms-server - Timing: 31 2017-05-03 13:51:35,507 INFO lifecycle - event: {"request": "764", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "end: handle", "time": "31 ms"} 2017-05-03 13:51:35,507 INFO lifecycle - event: {"request": "764", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: chain", "time": "31 ms"} 2017-05-03 13:51:35,507 INFO lifecycle - event: {"request": "764", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: filter", "time": "32 ms"} 2017-05-03 13:52:29,215 INFO lifecycle - event: {"request": "765", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: filter", "path": "/xforms-server", "method": "POST"} 2017-05-03 13:52:29,215 INFO lifecycle - event: {"request": "765", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: chain", "path": "/xforms-server", "method": "POST", "wait": "0"} 2017-05-03 13:52:29,216 INFO lifecycle - event: {"request": "765", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "start: handle"} 2017-05-03 13:52:29,216 INFO ProcessorService - /xforms-server - Received request 2017-05-03 13:52:29,227 INFO lifecycle - event: {"request": "765", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "ajax with update events", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77"} 2017-05-03 13:52:29,228 INFO lifecycle - event: {"request": "765", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "before document lock", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77"} 2017-05-03 13:52:29,228 INFO lifecycle - event: {"request": "765", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "got document lock", "path": "/xforms-server", "method": "POST", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77", "wait": "0"} 2017-05-03 13:52:29,326 WARN XFormsServer - xxf:instance() - instance not found {instance id: "fr-xforms-inspector-input"} 2017-05-03 13:52:29,366 INFO lifecycle - event: {"request": "765", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "after cacheOrStore", "document cache current size": "35", "document cache max size": "50"} 2017-05-03 13:52:29,366 INFO ProcessorService - /xforms-server - Timing: 150 2017-05-03 13:52:29,367 INFO lifecycle - event: {"request": "765", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "end: handle", "time": "151 ms"} 2017-05-03 13:52:29,367 INFO lifecycle - event: {"request": "765", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: chain", "time": "152 ms"} 2017-05-03 13:52:29,368 INFO lifecycle - event: {"request": "765", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: filter", "time": "152 ms"} 2017-05-03 13:52:29,568 INFO lifecycle - event: {"request": "766", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: filter", "path": "/xforms-server", "method": "POST"} 2017-05-03 13:52:29,568 INFO lifecycle - event: {"request": "766", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: chain", "path": "/xforms-server", "method": "POST", "wait": "0"} 2017-05-03 13:52:29,569 INFO lifecycle - event: {"request": "766", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "start: handle"} 2017-05-03 13:52:29,569 INFO ProcessorService - /xforms-server - Received request 2017-05-03 13:52:29,577 INFO lifecycle - event: {"request": "766", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "ajax with update events", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77"} 2017-05-03 13:52:29,577 INFO lifecycle - event: {"request": "766", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "before document lock", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77"} 2017-05-03 13:52:29,578 INFO lifecycle - event: {"request": "766", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "got document lock", "path": "/xforms-server", "method": "POST", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77", "wait": "1"} 2017-05-03 13:52:29,580 INFO lifecycle - event: {"request": "766", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "after cacheOrStore", "document cache current size": "35", "document cache max size": "50"} 2017-05-03 13:52:29,580 INFO ProcessorService - /xforms-server - Timing: 11 2017-05-03 13:52:29,581 INFO lifecycle - event: {"request": "766", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "end: handle", "time": "12 ms"} 2017-05-03 13:52:29,581 INFO lifecycle - event: {"request": "766", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: chain", "time": "13 ms"} 2017-05-03 13:52:29,581 INFO lifecycle - event: {"request": "766", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: filter", "time": "13 ms"} 2017-05-03 13:52:31,122 INFO lifecycle - event: {"request": "767", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: filter", "path": "/xforms-server", "method": "POST"} 2017-05-03 13:52:31,122 INFO lifecycle - event: {"request": "767", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: chain", "path": "/xforms-server", "method": "POST", "wait": "0"} 2017-05-03 13:52:31,123 INFO lifecycle - event: {"request": "767", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "start: handle"} 2017-05-03 13:52:31,123 INFO ProcessorService - /xforms-server - Received request 2017-05-03 13:52:31,131 INFO lifecycle - event: {"request": "767", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "ajax with update events", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77"} 2017-05-03 13:52:31,131 INFO lifecycle - event: {"request": "767", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "before document lock", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77"} 2017-05-03 13:52:31,131 INFO lifecycle - event: {"request": "767", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "got document lock", "path": "/xforms-server", "method": "POST", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77", "wait": "0"} 2017-05-03 13:52:31,235 WARN XFormsServer - xxf:instance() - instance not found {instance id: "fr-xforms-inspector-input"} 2017-05-03 13:52:31,326 WARN XFormsServer - xxf:instance() - instance not found {instance id: "fr-xforms-inspector-input"} 2017-05-03 13:52:31,393 INFO lifecycle - event: {"request": "767", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "after cacheOrStore", "document cache current size": "35", "document cache max size": "50"} 2017-05-03 13:52:31,393 INFO ProcessorService - /xforms-server - Timing: 270 2017-05-03 13:52:31,394 INFO lifecycle - event: {"request": "767", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "end: handle", "time": "272 ms"} 2017-05-03 13:52:31,394 INFO lifecycle - event: {"request": "767", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: chain", "time": "272 ms"} 2017-05-03 13:52:31,394 INFO lifecycle - event: {"request": "767", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: filter", "time": "272 ms"} 2017-05-03 13:52:35,572 INFO lifecycle - event: {"request": "768", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: filter", "path": "/xforms-server", "method": "POST"} 2017-05-03 13:52:35,572 INFO lifecycle - event: {"request": "768", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: chain", "path": "/xforms-server", "method": "POST", "wait": "0"} 2017-05-03 13:52:35,573 INFO lifecycle - event: {"request": "768", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "start: handle"} 2017-05-03 13:52:35,573 INFO ProcessorService - /xforms-server - Received request 2017-05-03 13:52:35,583 INFO lifecycle - event: {"request": "768", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "ajax with update events", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77"} 2017-05-03 13:52:35,584 INFO lifecycle - event: {"request": "768", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "before document lock", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77"} 2017-05-03 13:52:35,584 INFO lifecycle - event: {"request": "768", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "got document lock", "path": "/xforms-server", "method": "POST", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77", "wait": "0"} 2017-05-03 13:52:35,624 WARN XFormsServer - xxf:instance() - instance not found {instance id: "fr-xforms-inspector-input"} 2017-05-03 13:52:35,668 WARN XFormsServer - xxf:instance() - instance not found {instance id: "fr-xforms-inspector-input"} 2017-05-03 13:52:35,714 INFO lifecycle - event: {"request": "768", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "after cacheOrStore", "document cache current size": "35", "document cache max size": "50"} 2017-05-03 13:52:35,714 INFO ProcessorService - /xforms-server - Timing: 141 2017-05-03 13:52:35,715 INFO lifecycle - event: {"request": "768", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "end: handle", "time": "143 ms"} 2017-05-03 13:52:35,715 INFO lifecycle - event: {"request": "768", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: chain", "time": "143 ms"} 2017-05-03 13:52:35,715 INFO lifecycle - event: {"request": "768", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: filter", "time": "143 ms"} 2017-05-03 13:52:35,904 INFO lifecycle - event: {"request": "769", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: filter", "path": "/xforms-server", "method": "POST"} 2017-05-03 13:52:35,904 INFO lifecycle - event: {"request": "769", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: chain", "path": "/xforms-server", "method": "POST", "wait": "0"} 2017-05-03 13:52:35,905 INFO lifecycle - event: {"request": "769", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "start: handle"} 2017-05-03 13:52:35,905 INFO ProcessorService - /xforms-server - Received request 2017-05-03 13:52:35,913 INFO lifecycle - event: {"request": "769", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "ajax with update events", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77"} 2017-05-03 13:52:35,914 INFO lifecycle - event: {"request": "769", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "before document lock", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77"} 2017-05-03 13:52:35,914 INFO lifecycle - event: {"request": "769", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "got document lock", "path": "/xforms-server", "method": "POST", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77", "wait": "0"} 2017-05-03 13:52:35,916 INFO lifecycle - event: {"request": "769", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "after cacheOrStore", "document cache current size": "35", "document cache max size": "50"} 2017-05-03 13:52:35,917 INFO ProcessorService - /xforms-server - Timing: 12 2017-05-03 13:52:35,917 INFO lifecycle - event: {"request": "769", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "end: handle", "time": "12 ms"} 2017-05-03 13:52:35,917 INFO lifecycle - event: {"request": "769", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: chain", "time": "13 ms"} 2017-05-03 13:52:35,917 INFO lifecycle - event: {"request": "769", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: filter", "time": "13 ms"} 2017-05-03 13:53:51,527 INFO lifecycle - event: {"request": "770", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: filter", "path": "/xforms-server", "method": "POST"} 2017-05-03 13:53:51,527 INFO lifecycle - event: {"request": "770", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: chain", "path": "/xforms-server", "method": "POST", "wait": "0"} 2017-05-03 13:53:51,529 INFO lifecycle - event: {"request": "770", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "start: handle"} 2017-05-03 13:53:51,529 INFO ProcessorService - /xforms-server - Received request 2017-05-03 13:53:51,540 INFO lifecycle - event: {"request": "770", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "ajax with update events", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77"} 2017-05-03 13:53:51,540 INFO lifecycle - event: {"request": "770", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "before document lock", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77"} 2017-05-03 13:53:51,540 INFO lifecycle - event: {"request": "770", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "got document lock", "path": "/xforms-server", "method": "POST", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77", "wait": "0"} 2017-05-03 13:53:51,543 INFO lifecycle - event: {"request": "770", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "fr", "message": "start: process", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77", "scope": "oxf.fr.detail.process", "name": "test"} 2017-05-03 13:53:51,545 INFO lifecycle - event: {"request": "770", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "fr", "message": "end: process", "time": "2 ms"} 2017-05-03 13:53:51,548 INFO lifecycle - event: {"request": "770", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "after cacheOrStore", "document cache current size": "35", "document cache max size": "50"} 2017-05-03 13:53:51,548 INFO ProcessorService - /xforms-server - Timing: 19 2017-05-03 13:53:51,548 INFO lifecycle - event: {"request": "770", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "end: handle", "time": "20 ms"} 2017-05-03 13:53:51,549 INFO lifecycle - event: {"request": "770", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: chain", "time": "21 ms"} 2017-05-03 13:53:51,549 INFO lifecycle - event: {"request": "770", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: filter", "time": "22 ms"} 2017-05-03 13:53:51,778 INFO lifecycle - event: {"request": "771", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: filter", "path": "/xforms-server", "method": "POST"} 2017-05-03 13:53:51,778 INFO lifecycle - event: {"request": "771", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: chain", "path": "/xforms-server", "method": "POST", "wait": "0"} 2017-05-03 13:53:51,779 INFO lifecycle - event: {"request": "771", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "start: handle"} 2017-05-03 13:53:51,779 INFO ProcessorService - /xforms-server - Received request 2017-05-03 13:53:51,794 INFO lifecycle - event: {"request": "771", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "ajax with update events", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77"} 2017-05-03 13:53:51,794 INFO lifecycle - event: {"request": "771", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "before document lock", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77"} 2017-05-03 13:53:51,794 INFO lifecycle - event: {"request": "771", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "got document lock", "path": "/xforms-server", "method": "POST", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77", "wait": "0"} 2017-05-03 13:53:51,871 WARN XFormsServer - xxf:instance() - instance not found {instance id: "fr-xforms-inspector-input"} 2017-05-03 13:53:51,910 INFO lifecycle - event: {"request": "771", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "after cacheOrStore", "document cache current size": "35", "document cache max size": "50"} 2017-05-03 13:53:51,911 INFO ProcessorService - /xforms-server - Timing: 132 2017-05-03 13:53:51,911 INFO lifecycle - event: {"request": "771", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "end: handle", "time": "133 ms"} 2017-05-03 13:53:51,911 INFO lifecycle - event: {"request": "771", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: chain", "time": "133 ms"} 2017-05-03 13:53:51,911 INFO lifecycle - event: {"request": "771", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: filter", "time": "133 ms"} 2017-05-03 13:53:52,126 INFO lifecycle - event: {"request": "772", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: filter", "path": "/fr/orbeon/builder/edit/82123a4f182463064078e2ef1eab8ecc42232047", "method": "POST"} 2017-05-03 13:53:52,126 INFO lifecycle - event: {"request": "772", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: chain", "path": "/fr/orbeon/builder/edit/82123a4f182463064078e2ef1eab8ecc42232047", "method": "POST", "wait": "0"} 2017-05-03 13:53:52,127 INFO lifecycle - event: {"request": "772", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "start: handle"} 2017-05-03 13:53:52,127 INFO ProcessorService - /fr/orbeon/builder/edit/82123a4f182463064078e2ef1eab8ecc42232047 - Received request 2017-05-03 13:53:52,152 INFO lifecycle - event: {"request": "772", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "before document lock", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77"} 2017-05-03 13:53:52,153 INFO lifecycle - event: {"request": "772", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "got document lock", "path": "/fr/orbeon/builder/edit/82123a4f182463064078e2ef1eab8ecc42232047", "method": "POST", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77", "wait": "0"} 2017-05-03 13:53:52,199 INFO lifecycle - event: {"request": "772", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "after cacheOrStore", "document cache current size": "35", "document cache max size": "50"} 2017-05-03 13:53:52,200 INFO lifecycle - event: {"request": "773", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "start: handle", "path": "/fr/DatosXMLDoc/DatosXMLDoc/test", "method": "POST"} 2017-05-03 13:53:52,200 INFO ProcessorService - /fr/DatosXMLDoc/DatosXMLDoc/test - Received request 2017-05-03 13:53:52,323 INFO lifecycle - event: {"request": "773", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "new form session", "uuid": "5820a19c29a0b272cbf5264e867e18a4154d71a4"} 2017-05-03 13:53:52,388 WARN XFormsServer - xxf:instance() - instance not found {instance id: "fr-xforms-inspector-input"} 2017-05-03 13:53:52,388 WARN XFormsServer - xxf:instance() - instance not found {instance id: ""} 2017-05-03 13:53:52,447 INFO lifecycle - event: {"request": "774", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "start: handle", "path": "/xforms-sandbox/service/zip-states_MT05", "method": "GET"} 2017-05-03 13:53:52,448 INFO ProcessorService - /xforms-sandbox/service/zip-states_MT05 - Received request 2017-05-03 13:53:52,456 INFO PageFlowControllerProcessor - not found {controller: "oxf:/apps/xforms-sandbox/page-flow.xml", method: "GET", path: "/xforms-sandbox/service/zip-states_MT05", resource: "/apps/xforms-sandbox/services/zip-states_MT05.xpl"} 2017-05-03 13:53:52,456 INFO ProcessorService - /xforms-sandbox/service/zip-states_MT05 - Timing: 9 2017-05-03 13:53:52,457 INFO lifecycle - event: {"request": "774", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "end: handle", "time": "9 ms"} 2017-05-03 13:53:52,459 ERROR XFormsServer - xforms-submit-error - xf:submission for submission id: get-itemset, error code received when submitting instance: 404 2017-05-03 13:53:52,569 INFO lifecycle - event: {"request": "773", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "after cacheOrStore", "document cache current size": "36", "document cache max size": "50"} 2017-05-03 13:53:52,612 INFO ProcessorService - /fr/DatosXMLDoc/DatosXMLDoc/test - Timing: 412 2017-05-03 13:53:52,613 INFO lifecycle - event: {"request": "773", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "end: handle", "time": "413 ms"} 2017-05-03 13:53:52,618 INFO ProcessorService - /fr/orbeon/builder/edit/82123a4f182463064078e2ef1eab8ecc42232047 - Timing: 491 2017-05-03 13:53:52,620 INFO lifecycle - event: {"request": "772", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "end: handle", "time": "492 ms"} 2017-05-03 13:53:52,620 INFO lifecycle - event: {"request": "772", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: chain", "time": "494 ms"} 2017-05-03 13:53:52,621 INFO lifecycle - event: {"request": "772", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: filter", "time": "494 ms"} 2017-05-03 13:53:53,628 INFO lifecycle - event: {"request": "775", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: filter", "path": "/xforms-server", "method": "POST"} 2017-05-03 13:53:53,628 INFO lifecycle - event: {"request": "775", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: chain", "path": "/xforms-server", "method": "POST", "wait": "0"} 2017-05-03 13:53:53,629 INFO lifecycle - event: {"request": "775", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "start: handle"} 2017-05-03 13:53:53,629 INFO ProcessorService - /xforms-server - Received request 2017-05-03 13:53:53,639 INFO lifecycle - event: {"request": "775", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "ajax with update events", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77"} 2017-05-03 13:53:53,640 INFO lifecycle - event: {"request": "775", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "before document lock", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77"} 2017-05-03 13:53:53,640 INFO lifecycle - event: {"request": "775", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "got document lock", "path": "/xforms-server", "method": "POST", "uuid": "e6140203a1d83bdc2552eb7880e018ee23892c77", "wait": "0"} 2017-05-03 13:53:53,696 WARN XFormsServer - xxf:instance() - instance not found {instance id: "fr-xforms-inspector-input"} 2017-05-03 13:53:53,738 INFO lifecycle - event: {"request": "775", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "after cacheOrStore", "document cache current size": "36", "document cache max size": "50"} 2017-05-03 13:53:53,738 INFO ProcessorService - /xforms-server - Timing: 109 2017-05-03 13:53:53,739 INFO lifecycle - event: {"request": "775", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "end: handle", "time": "110 ms"} 2017-05-03 13:53:53,739 INFO lifecycle - event: {"request": "775", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: chain", "time": "111 ms"} 2017-05-03 13:53:53,739 INFO lifecycle - event: {"request": "775", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: filter", "time": "111 ms"} 2017-05-03 13:53:56,150 INFO lifecycle - event: {"request": "776", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: filter", "path": "/xforms-server", "method": "POST"} 2017-05-03 13:53:56,150 INFO lifecycle - event: {"request": "776", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: chain", "path": "/xforms-server", "method": "POST", "wait": "0"} 2017-05-03 13:53:56,151 INFO lifecycle - event: {"request": "776", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "start: handle"} 2017-05-03 13:53:56,151 INFO ProcessorService - /xforms-server - Received request 2017-05-03 13:53:56,163 INFO lifecycle - event: {"request": "776", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "ajax with update events", "uuid": "5820a19c29a0b272cbf5264e867e18a4154d71a4"} 2017-05-03 13:53:56,163 INFO lifecycle - event: {"request": "776", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "before document lock", "uuid": "5820a19c29a0b272cbf5264e867e18a4154d71a4"} 2017-05-03 13:53:56,163 INFO lifecycle - event: {"request": "776", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "got document lock", "path": "/xforms-server", "method": "POST", "uuid": "5820a19c29a0b272cbf5264e867e18a4154d71a4", "wait": "0"} 2017-05-03 13:53:56,187 INFO lifecycle - event: {"request": "776", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "after cacheOrStore", "document cache current size": "36", "document cache max size": "50"} 2017-05-03 13:53:56,187 INFO ProcessorService - /xforms-server - Timing: 36 2017-05-03 13:53:56,188 INFO lifecycle - event: {"request": "776", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "end: handle", "time": "36 ms"} 2017-05-03 13:53:56,188 INFO lifecycle - event: {"request": "776", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: chain", "time": "38 ms"} 2017-05-03 13:53:56,188 INFO lifecycle - event: {"request": "776", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: filter", "time": "38 ms"} 2017-05-03 13:53:56,653 INFO lifecycle - event: {"request": "777", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: filter", "path": "/xforms-server", "method": "POST"} 2017-05-03 13:53:56,653 INFO lifecycle - event: {"request": "777", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: chain", "path": "/xforms-server", "method": "POST", "wait": "0"} 2017-05-03 13:53:56,655 INFO lifecycle - event: {"request": "777", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "start: handle"} 2017-05-03 13:53:56,655 INFO ProcessorService - /xforms-server - Received request 2017-05-03 13:53:56,667 INFO lifecycle - event: {"request": "777", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "ajax with update events", "uuid": "5820a19c29a0b272cbf5264e867e18a4154d71a4"} 2017-05-03 13:53:56,667 INFO lifecycle - event: {"request": "777", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "before document lock", "uuid": "5820a19c29a0b272cbf5264e867e18a4154d71a4"} 2017-05-03 13:53:56,667 INFO lifecycle - event: {"request": "777", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "got document lock", "path": "/xforms-server", "method": "POST", "uuid": "5820a19c29a0b272cbf5264e867e18a4154d71a4", "wait": "0"} 2017-05-03 13:53:56,689 INFO lifecycle - event: {"request": "777", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "after cacheOrStore", "document cache current size": "36", "document cache max size": "50"} 2017-05-03 13:53:56,689 INFO ProcessorService - /xforms-server - Timing: 34 2017-05-03 13:53:56,689 INFO lifecycle - event: {"request": "777", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "end: handle", "time": "34 ms"} 2017-05-03 13:53:56,689 INFO lifecycle - event: {"request": "777", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: chain", "time": "36 ms"} 2017-05-03 13:53:56,690 INFO lifecycle - event: {"request": "777", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: filter", "time": "37 ms"} 2017-05-03 13:53:58,336 INFO lifecycle - event: {"request": "778", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: filter", "path": "/xforms-server", "method": "POST"} 2017-05-03 13:53:58,337 INFO lifecycle - event: {"request": "778", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: chain", "path": "/xforms-server", "method": "POST", "wait": "0"} 2017-05-03 13:53:58,337 INFO lifecycle - event: {"request": "778", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "start: handle"} 2017-05-03 13:53:58,337 INFO ProcessorService - /xforms-server - Received request 2017-05-03 13:53:58,346 INFO lifecycle - event: {"request": "778", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "ajax with update events", "uuid": "5820a19c29a0b272cbf5264e867e18a4154d71a4"} 2017-05-03 13:53:58,346 INFO lifecycle - event: {"request": "778", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "before document lock", "uuid": "5820a19c29a0b272cbf5264e867e18a4154d71a4"} 2017-05-03 13:53:58,346 INFO lifecycle - event: {"request": "778", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "got document lock", "path": "/xforms-server", "method": "POST", "uuid": "5820a19c29a0b272cbf5264e867e18a4154d71a4", "wait": "0"} 2017-05-03 13:53:58,350 INFO lifecycle - event: {"request": "778", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "after cacheOrStore", "document cache current size": "36", "document cache max size": "50"} 2017-05-03 13:53:58,350 INFO ProcessorService - /xforms-server - Timing: 13 2017-05-03 13:53:58,351 INFO lifecycle - event: {"request": "778", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "end: handle", "time": "13 ms"} 2017-05-03 13:53:58,351 INFO lifecycle - event: {"request": "778", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: chain", "time": "14 ms"} 2017-05-03 13:53:58,351 INFO lifecycle - event: {"request": "778", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: filter", "time": "15 ms"} 2017-05-03 13:53:59,456 INFO lifecycle - event: {"request": "779", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: filter", "path": "/xforms-server", "method": "POST"} 2017-05-03 13:53:59,456 INFO lifecycle - event: {"request": "779", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "start: chain", "path": "/xforms-server", "method": "POST", "wait": "0"} 2017-05-03 13:53:59,457 INFO lifecycle - event: {"request": "779", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "start: handle"} 2017-05-03 13:53:59,457 INFO ProcessorService - /xforms-server - Received request 2017-05-03 13:53:59,467 INFO lifecycle - event: {"request": "779", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "ajax with update events", "uuid": "5820a19c29a0b272cbf5264e867e18a4154d71a4"} 2017-05-03 13:53:59,467 INFO lifecycle - event: {"request": "779", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "before document lock", "uuid": "5820a19c29a0b272cbf5264e867e18a4154d71a4"} 2017-05-03 13:53:59,468 INFO lifecycle - event: {"request": "779", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "got document lock", "path": "/xforms-server", "method": "POST", "uuid": "5820a19c29a0b272cbf5264e867e18a4154d71a4", "wait": "0"} 2017-05-03 13:53:59,483 WARN XFormsServer - xxf:instance() - instance not found {instance id: ""} 2017-05-03 13:53:59,520 INFO lifecycle - event: {"request": "779", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "xforms", "message": "after cacheOrStore", "document cache current size": "36", "document cache max size": "50"} 2017-05-03 13:53:59,520 INFO ProcessorService - /xforms-server - Timing: 63 2017-05-03 13:53:59,520 INFO lifecycle - event: {"request": "779", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "service", "message": "end: handle", "time": "64 ms"} 2017-05-03 13:53:59,520 INFO lifecycle - event: {"request": "779", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: chain", "time": "64 ms"} 2017-05-03 13:53:59,520 INFO lifecycle - event: {"request": "779", "session": "45C57860C839B42DEEA5F1A183CFC415", "source": "limiter", "message": "end: filter", "time": "64 ms"}