2018-08-24 12:23:43,316 INFO lifecycle - event: {"request": "554", "session": "034A98241971E610710796029F506A97", "source": "limiter", "message": "start: filter", "path": "/xforms-server", "method": "POST"} 2018-08-24 12:23:43,316 INFO lifecycle - event: {"request": "554", "session": "034A98241971E610710796029F506A97", "source": "limiter", "message": "start: chain", "path": "/xforms-server", "method": "POST", "wait": "0"} 2018-08-24 12:23:43,316 INFO lifecycle - event: {"request": "554", "session": "034A98241971E610710796029F506A97", "source": "service", "message": "start: handle"} 2018-08-24 12:23:43,316 INFO ProcessorService - /xforms-server - Received request 2018-08-24 12:23:43,320 INFO lifecycle - event: {"request": "554", "session": "034A98241971E610710796029F506A97", "source": "xforms", "message": "ajax with update events", "uuid": "eb0858b2d06bd3c48ec476e680b11f0048541db0"} 2018-08-24 12:23:43,320 INFO lifecycle - event: {"request": "554", "session": "034A98241971E610710796029F506A97", "source": "xforms", "message": "before document lock", "uuid": "eb0858b2d06bd3c48ec476e680b11f0048541db0"} 2018-08-24 12:23:43,320 INFO lifecycle - event: {"request": "554", "session": "034A98241971E610710796029F506A97", "source": "xforms", "message": "got document lock", "path": "/xforms-server", "method": "POST", "uuid": "eb0858b2d06bd3c48ec476e680b11f0048541db0", "wait": "0"} 2018-08-24 12:23:43,321 INFO lifecycle - event: {"request": "554", "session": "034A98241971E610710796029F506A97", "source": "fr", "message": "start: process", "uuid": "eb0858b2d06bd3c48ec476e680b11f0048541db0", "scope": "oxf.fr.detail.process", "name": "test"} 2018-08-24 12:23:43,321 INFO lifecycle - event: {"request": "554", "session": "034A98241971E610710796029F506A97", "source": "fr", "message": "end: process", "time": "0 ms"} 2018-08-24 12:23:43,322 INFO lifecycle - event: {"request": "554", "session": "034A98241971E610710796029F506A97", "source": "xforms", "message": "after cacheOrStore", "document cache current size": "42", "document cache max size": "50"} 2018-08-24 12:23:43,322 INFO ProcessorService - /xforms-server - Timing: 6 2018-08-24 12:23:43,322 INFO lifecycle - event: {"request": "554", "session": "034A98241971E610710796029F506A97", "source": "service", "message": "end: handle", "time": "6 ms"} 2018-08-24 12:23:43,322 INFO lifecycle - event: {"request": "554", "session": "034A98241971E610710796029F506A97", "source": "limiter", "message": "end: chain", "time": "6 ms"} 2018-08-24 12:23:43,322 INFO lifecycle - event: {"request": "554", "session": "034A98241971E610710796029F506A97", "source": "limiter", "message": "end: filter", "time": "6 ms"} 2018-08-24 12:23:43,465 INFO lifecycle - event: {"request": "555", "session": "034A98241971E610710796029F506A97", "source": "limiter", "message": "start: filter", "path": "/xforms-server", "method": "POST"} 2018-08-24 12:23:43,465 INFO lifecycle - event: {"request": "555", "session": "034A98241971E610710796029F506A97", "source": "limiter", "message": "start: chain", "path": "/xforms-server", "method": "POST", "wait": "0"} 2018-08-24 12:23:43,465 INFO lifecycle - event: {"request": "555", "session": "034A98241971E610710796029F506A97", "source": "service", "message": "start: handle"} 2018-08-24 12:23:43,465 INFO ProcessorService - /xforms-server - Received request 2018-08-24 12:23:43,466 INFO lifecycle - event: {"request": "555", "session": "034A98241971E610710796029F506A97", "source": "xforms", "message": "ajax with update events", "uuid": "eb0858b2d06bd3c48ec476e680b11f0048541db0"} 2018-08-24 12:23:43,466 INFO lifecycle - event: {"request": "555", "session": "034A98241971E610710796029F506A97", "source": "xforms", "message": "before document lock", "uuid": "eb0858b2d06bd3c48ec476e680b11f0048541db0"} 2018-08-24 12:23:43,466 INFO lifecycle - event: {"request": "555", "session": "034A98241971E610710796029F506A97", "source": "xforms", "message": "got document lock", "path": "/xforms-server", "method": "POST", "uuid": "eb0858b2d06bd3c48ec476e680b11f0048541db0", "wait": "0"} 2018-08-24 12:23:43,495 INFO lifecycle - event: {"request": "555", "session": "034A98241971E610710796029F506A97", "source": "xforms", "message": "after cacheOrStore", "document cache current size": "42", "document cache max size": "50"} 2018-08-24 12:23:43,495 INFO ProcessorService - /xforms-server - Timing: 30 2018-08-24 12:23:43,495 INFO lifecycle - event: {"request": "555", "session": "034A98241971E610710796029F506A97", "source": "service", "message": "end: handle", "time": "30 ms"} 2018-08-24 12:23:43,495 INFO lifecycle - event: {"request": "555", "session": "034A98241971E610710796029F506A97", "source": "limiter", "message": "end: chain", "time": "30 ms"} 2018-08-24 12:23:43,495 INFO lifecycle - event: {"request": "555", "session": "034A98241971E610710796029F506A97", "source": "limiter", "message": "end: filter", "time": "30 ms"} 2018-08-24 12:23:43,543 INFO lifecycle - event: {"request": "556", "session": "034A98241971E610710796029F506A97", "source": "limiter", "message": "start: filter", "path": "/fr/orbeon/builder/new", "method": "POST"} 2018-08-24 12:23:43,543 INFO lifecycle - event: {"request": "556", "session": "034A98241971E610710796029F506A97", "source": "limiter", "message": "start: chain", "path": "/fr/orbeon/builder/new", "method": "POST", "wait": "0"} 2018-08-24 12:23:43,543 INFO lifecycle - event: {"request": "556", "session": "034A98241971E610710796029F506A97", "source": "service", "message": "start: handle"} 2018-08-24 12:23:43,543 INFO ProcessorService - /fr/orbeon/builder/new - Received request 2018-08-24 12:23:43,551 INFO lifecycle - event: {"request": "557", "session": "C21812B4376AE0846F1908F5BD9D1219", "source": "limiter", "message": "start: filter", "path": "/fr/service/persistence/crud/orbeon/builder/form/form.xhtml", "method": "GET"} 2018-08-24 12:23:43,551 INFO lifecycle - event: {"request": "557", "session": "C21812B4376AE0846F1908F5BD9D1219", "source": "limiter", "message": "start: chain", "path": "/fr/service/persistence/crud/orbeon/builder/form/form.xhtml", "method": "GET", "wait": "0"} 2018-08-24 12:23:43,551 WARN auth - not setting credentials headers because credentials are not found 2018-08-24 12:23:43,551 INFO lifecycle - event: {"request": "557", "session": "C21812B4376AE0846F1908F5BD9D1219", "source": "service", "message": "start: handle"} 2018-08-24 12:23:43,551 INFO ProcessorService - /fr/service/persistence/crud/orbeon/builder/form/form.xhtml - Received request 2018-08-24 12:23:43,554 INFO lifecycle - event: {"request": "558", "session": "C21812B4376AE0846F1908F5BD9D1219", "source": "service", "message": "start: handle", "path": "/fr/service/resource/crud/orbeon/builder/form/form.xhtml", "method": "GET"} 2018-08-24 12:23:43,554 INFO ProcessorService - /fr/service/resource/crud/orbeon/builder/form/form.xhtml - Received request 2018-08-24 12:23:43,560 INFO ProcessorService - /fr/service/resource/crud/orbeon/builder/form/form.xhtml - Timing: 6 2018-08-24 12:23:43,560 INFO lifecycle - event: {"request": "558", "session": "C21812B4376AE0846F1908F5BD9D1219", "source": "service", "message": "end: handle", "time": "6 ms"} 2018-08-24 12:23:43,561 INFO ProcessorService - /fr/service/persistence/crud/orbeon/builder/form/form.xhtml - Timing: 10 2018-08-24 12:23:43,561 INFO lifecycle - event: {"request": "557", "session": "C21812B4376AE0846F1908F5BD9D1219", "source": "service", "message": "end: handle", "time": "10 ms"} 2018-08-24 12:23:43,561 INFO lifecycle - event: {"request": "557", "session": "C21812B4376AE0846F1908F5BD9D1219", "source": "limiter", "message": "end: chain", "time": "10 ms"} 2018-08-24 12:23:43,562 INFO lifecycle - event: {"request": "557", "session": "C21812B4376AE0846F1908F5BD9D1219", "source": "limiter", "message": "end: filter", "time": "11 ms"} 2018-08-24 12:23:43,653 INFO lifecycle - event: {"request": "556", "session": "034A98241971E610710796029F506A97", "source": "xforms", "message": "new form session", "uuid": "5deb996365472a94c7731bc33d02d1b39208f321"} 2018-08-24 12:23:43,655 WARN XFormsServer - xxf:instance() - instance not found {instance id: "fr-form-attachments"} 2018-08-24 12:23:43,681 WARN XFormsServer - xxf:instance() - instance not found {instance id: "fr-form-attachments"} 2018-08-24 12:23:43,708 WARN XFormsServer - xxf:instance() - instance not found {instance id: "fr-form-attachments"} 2018-08-24 12:23:43,716 WARN XFormsServer - xxf:instance() - instance not found {instance id: "fr-form-attachments"} 2018-08-24 12:23:43,731 WARN XFormsServer - xf:dispatch - cannot find target, ignoring action {target id: "fb-custom-form-settings"} 2018-08-24 12:23:43,762 INFO lifecycle - event: {"request": "556", "session": "034A98241971E610710796029F506A97", "source": "xforms", "message": "after cacheOrStore", "document cache current size": "43", "document cache max size": "50"} 2018-08-24 12:23:43,784 INFO ProcessorService - /fr/orbeon/builder/new - Timing: 241 2018-08-24 12:23:43,784 INFO lifecycle - event: {"request": "556", "session": "034A98241971E610710796029F506A97", "source": "service", "message": "end: handle", "time": "241 ms"} 2018-08-24 12:23:43,784 INFO lifecycle - event: {"request": "556", "session": "034A98241971E610710796029F506A97", "source": "limiter", "message": "end: chain", "time": "241 ms"} 2018-08-24 12:23:43,784 INFO lifecycle - event: {"request": "556", "session": "034A98241971E610710796029F506A97", "source": "limiter", "message": "end: filter", "time": "241 ms"} 2018-08-24 12:23:44,260 INFO lifecycle - event: {"request": "559", "session": "034A98241971E610710796029F506A97", "source": "limiter", "message": "start: filter", "path": "/xforms-server", "method": "POST"} 2018-08-24 12:23:44,260 INFO lifecycle - event: {"request": "559", "session": "034A98241971E610710796029F506A97", "source": "limiter", "message": "start: chain", "path": "/xforms-server", "method": "POST", "wait": "0"} 2018-08-24 12:23:44,260 INFO lifecycle - event: {"request": "559", "session": "034A98241971E610710796029F506A97", "source": "service", "message": "start: handle"} 2018-08-24 12:23:44,260 INFO ProcessorService - /xforms-server - Received request 2018-08-24 12:23:44,262 INFO lifecycle - event: {"request": "559", "session": "034A98241971E610710796029F506A97", "source": "xforms", "message": "ajax with update events", "uuid": "eb0858b2d06bd3c48ec476e680b11f0048541db0"} 2018-08-24 12:23:44,262 INFO lifecycle - event: {"request": "559", "session": "034A98241971E610710796029F506A97", "source": "xforms", "message": "before document lock", "uuid": "eb0858b2d06bd3c48ec476e680b11f0048541db0"} 2018-08-24 12:23:44,262 INFO lifecycle - event: {"request": "559", "session": "034A98241971E610710796029F506A97", "source": "xforms", "message": "got document lock", "path": "/xforms-server", "method": "POST", "uuid": "eb0858b2d06bd3c48ec476e680b11f0048541db0", "wait": "0"} 2018-08-24 12:23:44,279 INFO lifecycle - event: {"request": "559", "session": "034A98241971E610710796029F506A97", "source": "xforms", "message": "after cacheOrStore", "document cache current size": "43", "document cache max size": "50"} 2018-08-24 12:23:44,279 INFO ProcessorService - /xforms-server - Timing: 19 2018-08-24 12:23:44,279 INFO lifecycle - event: {"request": "559", "session": "034A98241971E610710796029F506A97", "source": "service", "message": "end: handle", "time": "19 ms"} 2018-08-24 12:23:44,279 INFO lifecycle - event: {"request": "559", "session": "034A98241971E610710796029F506A97", "source": "limiter", "message": "end: chain", "time": "19 ms"} 2018-08-24 12:23:44,279 INFO lifecycle - event: {"request": "559", "session": "034A98241971E610710796029F506A97", "source": "limiter", "message": "end: filter", "time": "19 ms"}