Unable to save settings: an error occurred in the document service

Issues during installation, usage and configuring
otroccaz
Posts: 17
Joined: Wed Jan 16, 2019 4:57 pm

Re: Unable to save settings: an error occurred in the document service

Post by otroccaz » Mon Feb 04, 2019 7:52 am

Hello!

Here are the versions: Onlyoffice connector 2.1.3, Onlyoffice 9.6.632 and DocumentServer 5.2.2.3.
I just tried to save the parameters again to get a recent log file: I got the error message (an error occurred in the document service) but under DocumentServer\Log\docservice there is no file created today. Is there a parameter to modify in the json config files to have more complete logs?
Last edited by otroccaz on Mon Feb 04, 2019 3:15 pm, edited 1 time in total.

otroccaz
Posts: 17
Joined: Wed Jan 16, 2019 4:57 pm

Re: Unable to save settings: an error occurred in the document service

Post by otroccaz » Mon Feb 04, 2019 10:17 am

On the other hand, by setting nginx to have as much detail as possible, this is what I get under \DocumentServer\nginx\logs\nginx.error.log:

Code: Select all

2019/02/04 11:10:55 [debug] 8604#9320: post event 01B4C0B8
2019/02/04 11:10:55 [debug] 8604#9320: delete posted event 01B4C0B8
2019/02/04 11:10:55 [debug] 8604#9320: accept on [::]:8083, ready: 0
2019/02/04 11:10:55 [debug] 8604#9320: malloc: 01B7D2A8:256
2019/02/04 11:10:55 [debug] 8604#9320: *280 accept: [::1]:65417 fd:456
2019/02/04 11:10:55 [debug] 8604#9320: *280 event timer add: 456: 60000:3086889080
2019/02/04 11:10:55 [debug] 8604#9320: *280 reusable connection: 1
2019/02/04 11:10:55 [debug] 8604#9320: *280 select add event fd:456 ev:0
2019/02/04 11:10:55 [debug] 8604#9320: *280 post event 01B4C1A8
2019/02/04 11:10:55 [debug] 8604#9320: *280 delete posted event 01B4C1A8
2019/02/04 11:10:55 [debug] 8604#9320: *280 http wait request handler
2019/02/04 11:10:55 [debug] 8604#9320: *280 malloc: 01B7E118:256
2019/02/04 11:10:55 [debug] 8604#9320: *280 malloc: 01B74CA8:1024
2019/02/04 11:10:55 [debug] 8604#9320: *280 WSARecv: fd:456 rc:0 670 of 1024
2019/02/04 11:10:55 [debug] 8604#9320: *280 reusable connection: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 malloc: 01B7C078:4096
2019/02/04 11:10:55 [debug] 8604#9320: *280 http process request line
2019/02/04 11:10:55 [debug] 8604#9320: *280 http request line: "GET /healthcheck HTTP/1.0"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http uri: "/healthcheck"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http args: ""
2019/02/04 11:10:55 [debug] 8604#9320: *280 http exten: ""
2019/02/04 11:10:55 [debug] 8604#9320: *280 http process request header line
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "Connection: Keep-Alive"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "Host: localhost:8083"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "Max-Forwards: 10"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "X-Forwarded-For: 129.20.88.149, 129.20.126.25:34602"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "X-Forwarded-Host: onlyoffice-osur.univ-rennes1.fr/ds-vpath"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "X-Forwarded-Server: onlyoffice-osur.univ-rennes1.fr"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "THE-SCHEME: https"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "THE-HOST: onlyoffice-osur.univ-rennes1.fr"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "X-REWRITER-URL: https://onlyoffice-osur.univ-rennes1.fr"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "X-FORWARDED-PROTO: https"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "X-Original-URL: /ds-vpath/healthcheck"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "X-ARR-SSL: 2048|256|C=FR, O=Universit%C3%A9 de Rennes 1, CN=etoile-frontalufr-47.univ-rennes1.fr|C=FR, O=Universit%C3%A9 de Rennes 1, CN=etoile-frontalufr-47.univ-rennes1.fr"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "X-ARR-LOG-ID: 26df7777-5cee-46ce-930b-031ca504a5e0"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header done
2019/02/04 11:10:55 [debug] 8604#9320: *280 event timer del: 456: 3086889080
2019/02/04 11:10:55 [debug] 8604#9320: *280 generic phase: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 rewrite phase: 1
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script regex: "^/$"
2019/02/04 11:10:55 [notice] 8604#9320: *280 "^/$" does not match "/healthcheck", client: ::1, server: , request: "GET /healthcheck HTTP/1.0", host: "localhost:8083"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script regex: "^\/OfficeWeb(\/apps\/.*)$"
2019/02/04 11:10:55 [notice] 8604#9320: *280 "^\/OfficeWeb(\/apps\/.*)$" does not match "/healthcheck", client: ::1, server: , request: "GET /healthcheck HTTP/1.0", host: "localhost:8083"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script regex: "^(\/web-apps\/apps\/(?!api\/).*)$"
2019/02/04 11:10:55 [notice] 8604#9320: *280 "^(\/web-apps\/apps\/(?!api\/).*)$" does not match "/healthcheck", client: ::1, server: , request: "GET /healthcheck HTTP/1.0", host: "localhost:8083"
2019/02/04 11:10:55 [debug] 8604#9320: *280 test location: "/"
2019/02/04 11:10:55 [debug] 8604#9320: *280 test location: "v5.2.2-3/"
2019/02/04 11:10:55 [debug] 8604#9320: *280 test location: "info"
2019/02/04 11:10:55 [debug] 8604#9320: *280 test location: ~ "^(\/v[\d]+\.[\d]+\.[\d]+[\.|-][\d]+)?\/(web-apps\/apps\/api\/documents\/api\.js)$"
2019/02/04 11:10:55 [debug] 8604#9320: *280 test location: ~ "^(\/v[\d]+\.[\d]+\.[\d]+[\.|-][\d]+)?\/(web-apps)(\/.*\.json)$"
2019/02/04 11:10:55 [debug] 8604#9320: *280 test location: ~ "^(\/v[\d]+\.[\d]+\.[\d]+[\.|-][\d]+)?\/(web-apps|sdkjs|sdkjs-plugins|fonts)(\/.*)$"
2019/02/04 11:10:55 [debug] 8604#9320: *280 test location: ~ "^(\/cache\/files.*)(\/.*)"
2019/02/04 11:10:55 [debug] 8604#9320: *280 test location: ~ "^(\/v[\d]+\.[\d]+\.[\d]+[\.|-][\d]+)?(\/doc\/.*)"
2019/02/04 11:10:55 [debug] 8604#9320: *280 test location: ~ "^(\/v[\d]+\.[\d]+\.[\d]+[\.|-][\d]+)?(\/spellchecker)(\/.*)$"
2019/02/04 11:10:55 [debug] 8604#9320: *280 using configuration "/"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http cl:-1 max:104857600
2019/02/04 11:10:55 [debug] 8604#9320: *280 rewrite phase: 3
2019/02/04 11:10:55 [debug] 8604#9320: *280 post rewrite phase: 4
2019/02/04 11:10:55 [debug] 8604#9320: *280 generic phase: 5
2019/02/04 11:10:55 [debug] 8604#9320: *280 generic phase: 6
2019/02/04 11:10:55 [debug] 8604#9320: *280 generic phase: 7
2019/02/04 11:10:55 [debug] 8604#9320: *280 access phase: 8
2019/02/04 11:10:55 [debug] 8604#9320: *280 access phase: 9
2019/02/04 11:10:55 [debug] 8604#9320: *280 access phase: 10
2019/02/04 11:10:55 [debug] 8604#9320: *280 post access phase: 11
2019/02/04 11:10:55 [debug] 8604#9320: *280 http init upstream, client timer: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 http map started
2019/02/04 11:10:55 [debug] 8604#9320: *280 http map: "" "close"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http map started
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script var: "onlyoffice-osur.univ-rennes1.fr/ds-vpath"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script var: "onlyoffice-osur.univ-rennes1.fr/ds-vpath"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http map: "onlyoffice-osur.univ-rennes1.fr/ds-vpath" "onlyoffice-osur.univ-rennes1.fr/ds-vpath"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http map started
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script var: "https"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script var: "https"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http map: "https" "https"
2019/02/04 11:10:55 [debug] 8604#9320: *280 malloc: 00414E48:4096
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "Host: "
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script var: "localhost:8083"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "
"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: ""
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: ""
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "Connection: "
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script var: "close"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "
"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "X-Forwarded-Host: "
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script var: "onlyoffice-osur.univ-rennes1.fr/ds-vpath"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "
"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "X-Forwarded-Proto: "
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script var: "https"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "
"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "X-Forwarded-For: "
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script var: "129.20.88.149, 129.20.126.25:34602, ::1"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "
"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: ""
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: ""
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: ""
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: ""
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "Max-Forwards: 10"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "X-Forwarded-Server: onlyoffice-osur.univ-rennes1.fr"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "THE-SCHEME: https"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "THE-HOST: onlyoffice-osur.univ-rennes1.fr"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "X-REWRITER-URL: https://onlyoffice-osur.univ-rennes1.fr"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "X-Original-URL: /ds-vpath/healthcheck"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "X-ARR-SSL: 2048|256|C=FR, O=Universit%C3%A9 de Rennes 1, CN=etoile-frontalufr-47.univ-rennes1.fr|C=FR, O=Universit%C3%A9 de Rennes 1, CN=etoile-frontalufr-47.univ-rennes1.fr"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "X-ARR-LOG-ID: 26df7777-5cee-46ce-930b-031ca504a5e0"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header:
"GET /healthcheck HTTP/1.0
Host: localhost:8083
Connection: close
X-Forwarded-Host: onlyoffice-osur.univ-rennes1.fr/ds-vpath
X-Forwarded-Proto: https
X-Forwarded-For: 129.20.88.149, 129.20.126.25:34602, ::1
Max-Forwards: 10
X-Forwarded-Server: onlyoffice-osur.univ-rennes1.fr
THE-SCHEME: https
THE-HOST: onlyoffice-osur.univ-rennes1.fr
X-REWRITER-URL: https://onlyoffice-osur.univ-rennes1.fr
X-Original-URL: /ds-vpath/healthcheck
X-ARR-SSL: 2048|256|C=FR, O=Universit%C3%A9 de Rennes 1, CN=etoile-frontalufr-47.univ-rennes1.fr|C=FR, O=Universit%C3%A9 de Rennes 1, CN=etoile-frontalufr-47.univ-rennes1.fr
X-ARR-LOG-ID: 26df7777-5cee-46ce-930b-031ca504a5e0

"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http cleanup add: 01B7CF10
2019/02/04 11:10:55 [debug] 8604#9320: *280 get rr peer, try: 2
2019/02/04 11:10:55 [debug] 8604#9320: *280 get rr peer, current: 01B254BC -1
2019/02/04 11:10:55 [debug] 8604#9320: *280 stream socket 384
2019/02/04 11:10:55 [debug] 8604#9320: *280 connect to 127.0.0.1:8000, fd:384 #281
2019/02/04 11:10:55 [debug] 8604#9320: *280 select add event fd:384 ev:0
2019/02/04 11:10:55 [debug] 8604#9320: *280 select add event fd:384 ev:1
2019/02/04 11:10:55 [debug] 8604#9320: *280 http upstream connect: -2
2019/02/04 11:10:55 [debug] 8604#9320: *280 malloc: 0040DB50:128
2019/02/04 11:10:55 [debug] 8604#9320: *280 event timer add: 384: 60000:3086889080
2019/02/04 11:10:55 [debug] 8604#9320: *280 http finalize request: -4, "/healthcheck?" a:1, c:2
2019/02/04 11:10:55 [debug] 8604#9320: *280 http request count:2 blk:0
2019/02/04 11:10:55 [debug] 8604#9320: *280 post event 01B60610
2019/02/04 11:10:55 [debug] 8604#9320: *280 delete posted event 01B60610
2019/02/04 11:10:55 [debug] 8604#9320: *280 http upstream request: "/healthcheck?"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http upstream send request handler
2019/02/04 11:10:55 [debug] 8604#9320: *280 http upstream send request
2019/02/04 11:10:55 [debug] 8604#9320: *280 http upstream send request body
2019/02/04 11:10:55 [debug] 8604#9320: *280 chain writer buf fl:1 s:670
2019/02/04 11:10:55 [debug] 8604#9320: *280 chain writer in: 01B7CF2C
2019/02/04 11:10:55 [debug] 8604#9320: *280 WSASend: fd:384, s:670
2019/02/04 11:10:55 [debug] 8604#9320: *280 chain writer out: 00000000
2019/02/04 11:10:55 [debug] 8604#9320: *280 event timer del: 384: 3086889080
2019/02/04 11:10:55 [debug] 8604#9320: *280 select del event fd:384 ev:1
2019/02/04 11:10:55 [debug] 8604#9320: *280 event timer add: 384: 60000:3086889080
2019/02/04 11:10:55 [debug] 8604#9320: *280 post event 01B4C608
2019/02/04 11:10:55 [debug] 8604#9320: *280 delete posted event 01B4C608
2019/02/04 11:10:55 [debug] 8604#9320: *280 http upstream request: "/healthcheck?"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http upstream process header
2019/02/04 11:10:55 [debug] 8604#9320: *280 malloc: 00406A18:4096
2019/02/04 11:10:55 [debug] 8604#9320: *280 WSARecv: fd:384 rc:0 203 of 4096
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy status 200 "200 OK"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "X-Powered-By: Express"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "Content-Type: text/plain; charset=utf-8"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "Content-Length: 4"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "ETag: W/"4-X/5TO4MPCKAyY0ipFgr6/IraRNs""
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "Date: Mon, 04 Feb 2019 10:10:55 GMT"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "Connection: close"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header done
2019/02/04 11:10:55 [debug] 8604#9320: *280 HTTP/1.1 200 OK
Server: nginx
Date: Mon, 04 Feb 2019 10:10:55 GMT
Content-Type: text/plain; charset=utf-8
Content-Length: 4
Connection: keep-alive
X-Powered-By: Express
ETag: W/"4-X/5TO4MPCKAyY0ipFgr6/IraRNs"

2019/02/04 11:10:55 [debug] 8604#9320: *280 write new buf t:1 f:0 004151D0, pos 004151D0, size: 219 file: 0, size: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 http write filter: l:0 f:0 s:219
2019/02/04 11:10:55 [debug] 8604#9320: *280 http cacheable: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy filter init s:200 h:0 c:0 l:4
2019/02/04 11:10:55 [debug] 8604#9320: *280 http upstream process upstream
2019/02/04 11:10:55 [debug] 8604#9320: *280 pipe read upstream: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 pipe preread: 4
2019/02/04 11:10:55 [debug] 8604#9320: *280 pipe buf free s:0 t:1 f:0 00406A18, pos 00406ADF, size: 4 file: 0, size: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 pipe length: 4
2019/02/04 11:10:55 [debug] 8604#9320: *280 input buf #0
2019/02/04 11:10:55 [debug] 8604#9320: *280 pipe write downstream: 1
2019/02/04 11:10:55 [debug] 8604#9320: *280 pipe write downstream flush in
2019/02/04 11:10:55 [debug] 8604#9320: *280 http output filter "/healthcheck?"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http copy filter: "/healthcheck?"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http postpone filter "/healthcheck?" 00415340
2019/02/04 11:10:55 [debug] 8604#9320: *280 write old buf t:1 f:0 004151D0, pos 004151D0, size: 219 file: 0, size: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 write new buf t:1 f:0 00406A18, pos 00406ADF, size: 4 file: 0, size: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 http write filter: l:0 f:0 s:223
2019/02/04 11:10:55 [debug] 8604#9320: *280 http copy filter: 0 "/healthcheck?"
2019/02/04 11:10:55 [debug] 8604#9320: *280 pipe write downstream done
2019/02/04 11:10:55 [debug] 8604#9320: *280 event timer: 384, old: 3086889080, new: 3086889142
2019/02/04 11:10:55 [debug] 8604#9320: *280 http upstream exit: 00000000
2019/02/04 11:10:55 [debug] 8604#9320: *280 finalize http upstream request: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 finalize http proxy request
2019/02/04 11:10:55 [debug] 8604#9320: *280 free rr peer 2 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 close http upstream connection: 384
2019/02/04 11:10:55 [debug] 8604#9320: *280 free: 0040DB50, unused: 88
2019/02/04 11:10:55 [debug] 8604#9320: *280 event timer del: 384: 3086889080
2019/02/04 11:10:55 [debug] 8604#9320: *280 select del event fd:384 ev:0
2019/02/04 11:10:55 [debug] 8604#9320: *280 reusable connection: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 http upstream temp fd: -1
2019/02/04 11:10:55 [debug] 8604#9320: *280 http output filter "/healthcheck?"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http copy filter: "/healthcheck?"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http postpone filter "/healthcheck?" 01AAFC78
2019/02/04 11:10:55 [debug] 8604#9320: *280 write old buf t:1 f:0 004151D0, pos 004151D0, size: 219 file: 0, size: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 write old buf t:1 f:0 00406A18, pos 00406ADF, size: 4 file: 0, size: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 write new buf t:0 f:0 00000000, pos 00000000, size: 0 file: 0, size: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 http write filter: l:1 f:0 s:223
2019/02/04 11:10:55 [debug] 8604#9320: *280 http write filter limit 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 WSASend: fd:456, s:223
2019/02/04 11:10:55 [debug] 8604#9320: *280 http write filter 00000000
2019/02/04 11:10:55 [debug] 8604#9320: *280 http copy filter: 0 "/healthcheck?"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http finalize request: 0, "/healthcheck?" a:1, c:1
2019/02/04 11:10:55 [debug] 8604#9320: *280 set http keepalive handler
2019/02/04 11:10:55 [debug] 8604#9320: *280 http close request
2019/02/04 11:10:55 [debug] 8604#9320: *280 http log handler
2019/02/04 11:10:55 [debug] 8604#9320: *280 free: 00406A18
2019/02/04 11:10:55 [debug] 8604#9320: *280 free: 01B7C078, unused: 3
2019/02/04 11:10:55 [debug] 8604#9320: *280 free: 00414E48, unused: 2525
2019/02/04 11:10:55 [debug] 8604#9320: *280 free: 01B74CA8
2019/02/04 11:10:55 [debug] 8604#9320: *280 hc free: 00000000 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 hc busy: 00000000 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 tcp_nodelay
2019/02/04 11:10:55 [debug] 8604#9320: *280 reusable connection: 1
2019/02/04 11:10:55 [debug] 8604#9320: *280 event timer add: 456: 65000:3086894142
2019/02/04 11:10:55 [debug] 8604#9320: *280 post event 01B4C1A8
2019/02/04 11:10:55 [debug] 8604#9320: *280 delete posted event 01B4C1A8
2019/02/04 11:10:55 [debug] 8604#9320: *280 http keepalive handler
2019/02/04 11:10:55 [debug] 8604#9320: *280 malloc: 01B74CA8:1024
2019/02/04 11:10:55 [debug] 8604#9320: *280 WSARecv: fd:456 rc:0 763 of 1024
2019/02/04 11:10:55 [debug] 8604#9320: *280 reusable connection: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 malloc: 01B7C078:4096
2019/02/04 11:10:55 [debug] 8604#9320: *280 event timer del: 456: 3086894142
2019/02/04 11:10:55 [debug] 8604#9320: *280 http process request line
2019/02/04 11:10:55 [debug] 8604#9320: *280 http request line: "POST /coauthoring/CommandService.ashx HTTP/1.0"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http uri: "/coauthoring/CommandService.ashx"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http args: ""
2019/02/04 11:10:55 [debug] 8604#9320: *280 http exten: "ashx"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http process request header line
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "Connection: Keep-Alive"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "Content-Type: application/json"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "Host: localhost:8083"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "Max-Forwards: 10"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "X-Forwarded-For: 129.20.88.149, 129.20.126.25:34612"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "X-Forwarded-Host: onlyoffice-osur.univ-rennes1.fr/ds-vpath"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "X-Forwarded-Server: onlyoffice-osur.univ-rennes1.fr"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "THE-SCHEME: https"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "THE-HOST: onlyoffice-osur.univ-rennes1.fr"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "X-REWRITER-URL: https://onlyoffice-osur.univ-rennes1.fr"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "X-FORWARDED-PROTO: https"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "X-Original-URL: /ds-vpath/coauthoring/CommandService.ashx"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "X-ARR-SSL: 2048|256|C=FR, O=Universit%C3%A9 de Rennes 1, CN=etoile-frontalufr-47.univ-rennes1.fr|C=FR, O=Universit%C3%A9 de Rennes 1, CN=etoile-frontalufr-47.univ-rennes1.fr"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "X-ARR-LOG-ID: ed3e57ee-a23e-484b-ad32-bf2004264845"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "Content-Length: 15"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header done
2019/02/04 11:10:55 [debug] 8604#9320: *280 generic phase: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 rewrite phase: 1
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script regex: "^/$"
2019/02/04 11:10:55 [notice] 8604#9320: *280 "^/$" does not match "/coauthoring/CommandService.ashx", client: ::1, server: , request: "POST /coauthoring/CommandService.ashx HTTP/1.0", host: "localhost:8083"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script regex: "^\/OfficeWeb(\/apps\/.*)$"
2019/02/04 11:10:55 [notice] 8604#9320: *280 "^\/OfficeWeb(\/apps\/.*)$" does not match "/coauthoring/CommandService.ashx", client: ::1, server: , request: "POST /coauthoring/CommandService.ashx HTTP/1.0", host: "localhost:8083"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script regex: "^(\/web-apps\/apps\/(?!api\/).*)$"
2019/02/04 11:10:55 [notice] 8604#9320: *280 "^(\/web-apps\/apps\/(?!api\/).*)$" does not match "/coauthoring/CommandService.ashx", client: ::1, server: , request: "POST /coauthoring/CommandService.ashx HTTP/1.0", host: "localhost:8083"
2019/02/04 11:10:55 [debug] 8604#9320: *280 test location: "/"
2019/02/04 11:10:55 [debug] 8604#9320: *280 test location: "v5.2.2-3/"
2019/02/04 11:10:55 [debug] 8604#9320: *280 test location: "info"
2019/02/04 11:10:55 [debug] 8604#9320: *280 test location: ~ "^(\/v[\d]+\.[\d]+\.[\d]+[\.|-][\d]+)?\/(web-apps\/apps\/api\/documents\/api\.js)$"
2019/02/04 11:10:55 [debug] 8604#9320: *280 test location: ~ "^(\/v[\d]+\.[\d]+\.[\d]+[\.|-][\d]+)?\/(web-apps)(\/.*\.json)$"
2019/02/04 11:10:55 [debug] 8604#9320: *280 test location: ~ "^(\/v[\d]+\.[\d]+\.[\d]+[\.|-][\d]+)?\/(web-apps|sdkjs|sdkjs-plugins|fonts)(\/.*)$"
2019/02/04 11:10:55 [debug] 8604#9320: *280 test location: ~ "^(\/cache\/files.*)(\/.*)"
2019/02/04 11:10:55 [debug] 8604#9320: *280 test location: ~ "^(\/v[\d]+\.[\d]+\.[\d]+[\.|-][\d]+)?(\/doc\/.*)"
2019/02/04 11:10:55 [debug] 8604#9320: *280 test location: ~ "^(\/v[\d]+\.[\d]+\.[\d]+[\.|-][\d]+)?(\/spellchecker)(\/.*)$"
2019/02/04 11:10:55 [debug] 8604#9320: *280 using configuration "/"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http cl:15 max:104857600
2019/02/04 11:10:55 [debug] 8604#9320: *280 rewrite phase: 3
2019/02/04 11:10:55 [debug] 8604#9320: *280 post rewrite phase: 4
2019/02/04 11:10:55 [debug] 8604#9320: *280 generic phase: 5
2019/02/04 11:10:55 [debug] 8604#9320: *280 generic phase: 6
2019/02/04 11:10:55 [debug] 8604#9320: *280 generic phase: 7
2019/02/04 11:10:55 [debug] 8604#9320: *280 access phase: 8
2019/02/04 11:10:55 [debug] 8604#9320: *280 access phase: 9
2019/02/04 11:10:55 [debug] 8604#9320: *280 access phase: 10
2019/02/04 11:10:55 [debug] 8604#9320: *280 post access phase: 11
2019/02/04 11:10:55 [debug] 8604#9320: *280 http request body content length filter
2019/02/04 11:10:55 [debug] 8604#9320: *280 http read client request body
2019/02/04 11:10:55 [debug] 8604#9320: *280 WSARecv: fd:456 rc:-1 0 of 15
2019/02/04 11:10:55 [debug] 8604#9320: *280 WSARecv() not ready (10035: FormatMessage() error:(15105))
2019/02/04 11:10:55 [debug] 8604#9320: *280 http client request body recv -2
2019/02/04 11:10:55 [debug] 8604#9320: *280 http client request body rest 15
2019/02/04 11:10:55 [debug] 8604#9320: *280 event timer add: 456: 60000:3086889220
2019/02/04 11:10:55 [debug] 8604#9320: *280 http finalize request: -4, "/coauthoring/CommandService.ashx?" a:1, c:2
2019/02/04 11:10:55 [debug] 8604#9320: *280 http request count:2 blk:0
2019/02/04 11:10:55 [debug] 8604#9320: *280 post event 01B4C1A8
2019/02/04 11:10:55 [debug] 8604#9320: *280 delete posted event 01B4C1A8
2019/02/04 11:10:55 [debug] 8604#9320: *280 http run request: "/coauthoring/CommandService.ashx?"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http read client request body
2019/02/04 11:10:55 [debug] 8604#9320: *280 WSARecv: fd:456 rc:0 15 of 15
2019/02/04 11:10:55 [debug] 8604#9320: *280 http client request body recv 15
2019/02/04 11:10:55 [debug] 8604#9320: *280 http body new buf t:1 f:0 01B7CE2C, pos 01B7CE2C, size: 15 file: 0, size: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 http client request body rest 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 event timer del: 456: 3086889220
2019/02/04 11:10:55 [debug] 8604#9320: *280 http init upstream, client timer: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 http map started
2019/02/04 11:10:55 [debug] 8604#9320: *280 http map: "" "close"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http map started
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script var: "onlyoffice-osur.univ-rennes1.fr/ds-vpath"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script var: "onlyoffice-osur.univ-rennes1.fr/ds-vpath"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http map: "onlyoffice-osur.univ-rennes1.fr/ds-vpath" "onlyoffice-osur.univ-rennes1.fr/ds-vpath"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http map started
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script var: "https"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script var: "https"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http map: "https" "https"
2019/02/04 11:10:55 [debug] 8604#9320: *280 malloc: 00414E48:4096
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "Host: "
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script var: "localhost:8083"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "
"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: ""
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: ""
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "Connection: "
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script var: "close"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "
"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "X-Forwarded-Host: "
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script var: "onlyoffice-osur.univ-rennes1.fr/ds-vpath"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "
"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "X-Forwarded-Proto: "
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script var: "https"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "
"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "X-Forwarded-For: "
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script var: "129.20.88.149, 129.20.126.25:34612, ::1"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "
"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "Content-Length: "
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script var: "15"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "
"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: ""
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: ""
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "Content-Type: application/json"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "Max-Forwards: 10"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "X-Forwarded-Server: onlyoffice-osur.univ-rennes1.fr"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "THE-SCHEME: https"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "THE-HOST: onlyoffice-osur.univ-rennes1.fr"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "X-REWRITER-URL: https://onlyoffice-osur.univ-rennes1.fr"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "X-Original-URL: /ds-vpath/coauthoring/CommandService.ashx"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "X-ARR-SSL: 2048|256|C=FR, O=Universit%C3%A9 de Rennes 1, CN=etoile-frontalufr-47.univ-rennes1.fr|C=FR, O=Universit%C3%A9 de Rennes 1, CN=etoile-frontalufr-47.univ-rennes1.fr"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "X-ARR-LOG-ID: ed3e57ee-a23e-484b-ad32-bf2004264845"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header:
"POST /coauthoring/CommandService.ashx HTTP/1.0
Host: localhost:8083
Connection: close
X-Forwarded-Host: onlyoffice-osur.univ-rennes1.fr/ds-vpath
X-Forwarded-Proto: https
X-Forwarded-For: 129.20.88.149, 129.20.126.25:34612, ::1
Content-Length: 15
Content-Type: application/json
Max-Forwards: 10
X-Forwarded-Server: onlyoffice-osur.univ-rennes1.fr
THE-SCHEME: https
THE-HOST: onlyoffice-osur.univ-rennes1.fr
X-REWRITER-URL: https://onlyoffice-osur.univ-rennes1.fr
X-Original-URL: /ds-vpath/coauthoring/CommandService.ashx
X-ARR-SSL: 2048|256|C=FR, O=Universit%C3%A9 de Rennes 1, CN=etoile-frontalufr-47.univ-rennes1.fr|C=FR, O=Universit%C3%A9 de Rennes 1, CN=etoile-frontalufr-47.univ-rennes1.fr
X-ARR-LOG-ID: ed3e57ee-a23e-484b-ad32-bf2004264845

"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http cleanup add: 01B7D00C
2019/02/04 11:10:55 [debug] 8604#9320: *280 get rr peer, try: 2
2019/02/04 11:10:55 [debug] 8604#9320: *280 get rr peer, current: 01B25524 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 stream socket 384
2019/02/04 11:10:55 [debug] 8604#9320: *280 connect to [::1]:8000, fd:384 #282
2019/02/04 11:10:55 [debug] 8604#9320: *280 select add event fd:384 ev:0
2019/02/04 11:10:55 [debug] 8604#9320: *280 select add event fd:384 ev:1
2019/02/04 11:10:55 [debug] 8604#9320: *280 http upstream connect: -2
2019/02/04 11:10:55 [debug] 8604#9320: *280 malloc: 0040DB50:128
2019/02/04 11:10:55 [debug] 8604#9320: *280 event timer add: 384: 60000:3086889220
2019/02/04 11:10:55 [debug] 8604#9320: *280 post event 01B60610
2019/02/04 11:10:55 [debug] 8604#9320: *280 delete posted event 01B60610
2019/02/04 11:10:55 [debug] 8604#9320: *280 http upstream request: "/coauthoring/CommandService.ashx?"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http upstream send request handler
2019/02/04 11:10:55 [debug] 8604#9320: *280 http upstream send request
2019/02/04 11:10:55 [debug] 8604#9320: *280 http upstream send request body
2019/02/04 11:10:55 [debug] 8604#9320: *280 chain writer buf fl:0 s:763
2019/02/04 11:10:55 [debug] 8604#9320: *280 chain writer buf fl:1 s:15
2019/02/04 11:10:55 [debug] 8604#9320: *280 chain writer in: 01B7D038
2019/02/04 11:10:55 [debug] 8604#9320: *280 WSASend: fd:384, s:778
2019/02/04 11:10:55 [debug] 8604#9320: *280 chain writer out: 00000000
2019/02/04 11:10:55 [debug] 8604#9320: *280 event timer del: 384: 3086889220
2019/02/04 11:10:55 [debug] 8604#9320: *280 select del event fd:384 ev:1
2019/02/04 11:10:55 [debug] 8604#9320: *280 event timer add: 384: 60000:3086889220
2019/02/04 11:10:55 [debug] 8604#9320: *280 post event 01B4C608
2019/02/04 11:10:55 [debug] 8604#9320: *280 delete posted event 01B4C608
2019/02/04 11:10:55 [debug] 8604#9320: *280 http upstream request: "/coauthoring/CommandService.ashx?"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http upstream process header
2019/02/04 11:10:55 [debug] 8604#9320: *280 malloc: 00406A18:4096
2019/02/04 11:10:55 [debug] 8604#9320: *280 WSARecv: fd:384 rc:0 223 of 4096
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy status 200 "200 OK"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "X-Powered-By: Express"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "Content-Type: application/json"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "Content-Length: 31"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "ETag: W/"1f-xOG7OQCkPYW0F0RJR6HDUBFjeAM""
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "Date: Mon, 04 Feb 2019 10:10:55 GMT"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "Connection: close"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header done
2019/02/04 11:10:55 [debug] 8604#9320: *280 HTTP/1.1 200 OK
Server: nginx
Date: Mon, 04 Feb 2019 10:10:55 GMT
Content-Type: application/json
Content-Length: 31
Connection: keep-alive
Vary: Accept-Encoding
X-Powered-By: Express
ETag: W/"1f-xOG7OQCkPYW0F0RJR6HDUBFjeAM"

2019/02/04 11:10:55 [debug] 8604#9320: *280 write new buf t:1 f:0 00415334, pos 00415334, size: 235 file: 0, size: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 http write filter: l:0 f:0 s:235
2019/02/04 11:10:55 [debug] 8604#9320: *280 http cacheable: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy filter init s:200 h:0 c:0 l:31
2019/02/04 11:10:55 [debug] 8604#9320: *280 http upstream process upstream
2019/02/04 11:10:55 [debug] 8604#9320: *280 pipe read upstream: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 pipe preread: 31
2019/02/04 11:10:55 [debug] 8604#9320: *280 pipe buf free s:0 t:1 f:0 00406A18, pos 00406AD8, size: 31 file: 0, size: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 pipe length: 31
2019/02/04 11:10:55 [debug] 8604#9320: *280 input buf #0
2019/02/04 11:10:55 [debug] 8604#9320: *280 pipe write downstream: 1
2019/02/04 11:10:55 [debug] 8604#9320: *280 pipe write downstream flush in
2019/02/04 11:10:55 [debug] 8604#9320: *280 http output filter "/coauthoring/CommandService.ashx?"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http copy filter: "/coauthoring/CommandService.ashx?"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http postpone filter "/coauthoring/CommandService.ashx?" 01B7D040
2019/02/04 11:10:55 [debug] 8604#9320: *280 write old buf t:1 f:0 00415334, pos 00415334, size: 235 file: 0, size: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 write new buf t:1 f:0 00406A18, pos 00406AD8, size: 31 file: 0, size: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 http write filter: l:0 f:0 s:266
2019/02/04 11:10:55 [debug] 8604#9320: *280 http copy filter: 0 "/coauthoring/CommandService.ashx?"
2019/02/04 11:10:55 [debug] 8604#9320: *280 pipe write downstream done
2019/02/04 11:10:55 [debug] 8604#9320: *280 event timer: 384, old: 3086889220, new: 3086889236
2019/02/04 11:10:55 [debug] 8604#9320: *280 http upstream exit: 00000000
2019/02/04 11:10:55 [debug] 8604#9320: *280 finalize http upstream request: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 finalize http proxy request
2019/02/04 11:10:55 [debug] 8604#9320: *280 free rr peer 2 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 close http upstream connection: 384
2019/02/04 11:10:55 [debug] 8604#9320: *280 free: 0040DB50, unused: 88
2019/02/04 11:10:55 [debug] 8604#9320: *280 event timer del: 384: 3086889220
2019/02/04 11:10:55 [debug] 8604#9320: *280 select del event fd:384 ev:0
2019/02/04 11:10:55 [debug] 8604#9320: *280 reusable connection: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 http upstream temp fd: -1
2019/02/04 11:10:55 [debug] 8604#9320: *280 http output filter "/coauthoring/CommandService.ashx?"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http copy filter: "/coauthoring/CommandService.ashx?"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http postpone filter "/coauthoring/CommandService.ashx?" 01AAFC78
2019/02/04 11:10:55 [debug] 8604#9320: *280 write old buf t:1 f:0 00415334, pos 00415334, size: 235 file: 0, size: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 write old buf t:1 f:0 00406A18, pos 00406AD8, size: 31 file: 0, size: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 write new buf t:0 f:0 00000000, pos 00000000, size: 0 file: 0, size: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 http write filter: l:1 f:0 s:266
2019/02/04 11:10:55 [debug] 8604#9320: *280 http write filter limit 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 WSASend: fd:456, s:266
2019/02/04 11:10:55 [debug] 8604#9320: *280 http write filter 00000000
2019/02/04 11:10:55 [debug] 8604#9320: *280 http copy filter: 0 "/coauthoring/CommandService.ashx?"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http finalize request: 0, "/coauthoring/CommandService.ashx?" a:1, c:1
2019/02/04 11:10:55 [debug] 8604#9320: *280 set http keepalive handler
2019/02/04 11:10:55 [debug] 8604#9320: *280 http close request
2019/02/04 11:10:55 [debug] 8604#9320: *280 http log handler
2019/02/04 11:10:55 [debug] 8604#9320: *280 free: 00406A18
2019/02/04 11:10:55 [debug] 8604#9320: *280 free: 01B7C078, unused: 1
2019/02/04 11:10:55 [debug] 8604#9320: *280 free: 00414E48, unused: 2156
2019/02/04 11:10:55 [debug] 8604#9320: *280 select del event fd:456 ev:0
2019/02/04 11:10:55 [debug] 8604#9320: *280 free: 01B74CA8
2019/02/04 11:10:55 [debug] 8604#9320: *280 hc free: 00000000 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 hc busy: 00000000 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 reusable connection: 1
2019/02/04 11:10:55 [debug] 8604#9320: *280 event timer add: 456: 65000:3086894236
2019/02/04 11:10:55 [debug] 8604#9320: *280 post event 01B4C1A8
2019/02/04 11:10:55 [debug] 8604#9320: *280 delete posted event 01B4C1A8
2019/02/04 11:10:55 [debug] 8604#9320: *280 http keepalive handler
2019/02/04 11:10:55 [debug] 8604#9320: *280 malloc: 01B74CA8:1024
2019/02/04 11:10:55 [debug] 8604#9320: *280 WSARecv: fd:456 rc:-1 0 of 1024
2019/02/04 11:10:55 [debug] 8604#9320: *280 WSARecv() not ready (10035: FormatMessage() error:(15105))
2019/02/04 11:10:55 [debug] 8604#9320: *280 select add event fd:456 ev:0
2019/02/04 11:10:55 [debug] 8604#9320: *280 free: 01B74CA8
2019/02/04 11:10:55 [debug] 8604#9320: *280 post event 01B4C1A8
2019/02/04 11:10:55 [debug] 8604#9320: *280 delete posted event 01B4C1A8
2019/02/04 11:10:55 [debug] 8604#9320: *280 http keepalive handler
2019/02/04 11:10:55 [debug] 8604#9320: *280 malloc: 01B74CA8:1024
2019/02/04 11:10:55 [debug] 8604#9320: *280 WSARecv: fd:456 rc:0 740 of 1024
2019/02/04 11:10:55 [debug] 8604#9320: *280 reusable connection: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 malloc: 01B7C078:4096
2019/02/04 11:10:55 [debug] 8604#9320: *280 event timer del: 456: 3086894236
2019/02/04 11:10:55 [debug] 8604#9320: *280 http process request line
2019/02/04 11:10:55 [debug] 8604#9320: *280 http request line: "POST /ConvertService.ashx HTTP/1.0"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http uri: "/ConvertService.ashx"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http args: ""
2019/02/04 11:10:55 [debug] 8604#9320: *280 http exten: "ashx"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http process request header line
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "Connection: Keep-Alive"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "Content-Type: application/json"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "Host: localhost:8083"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "Max-Forwards: 10"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "X-Forwarded-For: 129.20.88.149, 129.20.126.25:34616"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "X-Forwarded-Host: onlyoffice-osur.univ-rennes1.fr/ds-vpath"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "X-Forwarded-Server: onlyoffice-osur.univ-rennes1.fr"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "THE-SCHEME: https"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "THE-HOST: onlyoffice-osur.univ-rennes1.fr"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "X-REWRITER-URL: https://onlyoffice-osur.univ-rennes1.fr"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "X-FORWARDED-PROTO: https"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "X-Original-URL: /ds-vpath/ConvertService.ashx"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "X-ARR-SSL: 2048|256|C=FR, O=Universit%C3%A9 de Rennes 1, CN=etoile-frontalufr-47.univ-rennes1.fr|C=FR, O=Universit%C3%A9 de Rennes 1, CN=etoile-frontalufr-47.univ-rennes1.fr"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "X-ARR-LOG-ID: 1722afc1-042e-4f92-a4ad-adc5ccd92771"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header: "Content-Length: 386"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http header done
2019/02/04 11:10:55 [debug] 8604#9320: *280 generic phase: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 rewrite phase: 1
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script regex: "^/$"
2019/02/04 11:10:55 [notice] 8604#9320: *280 "^/$" does not match "/ConvertService.ashx", client: ::1, server: , request: "POST /ConvertService.ashx HTTP/1.0", host: "localhost:8083"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script regex: "^\/OfficeWeb(\/apps\/.*)$"
2019/02/04 11:10:55 [notice] 8604#9320: *280 "^\/OfficeWeb(\/apps\/.*)$" does not match "/ConvertService.ashx", client: ::1, server: , request: "POST /ConvertService.ashx HTTP/1.0", host: "localhost:8083"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script regex: "^(\/web-apps\/apps\/(?!api\/).*)$"
2019/02/04 11:10:55 [notice] 8604#9320: *280 "^(\/web-apps\/apps\/(?!api\/).*)$" does not match "/ConvertService.ashx", client: ::1, server: , request: "POST /ConvertService.ashx HTTP/1.0", host: "localhost:8083"
2019/02/04 11:10:55 [debug] 8604#9320: *280 test location: "/"
2019/02/04 11:10:55 [debug] 8604#9320: *280 test location: "v5.2.2-3/"
2019/02/04 11:10:55 [debug] 8604#9320: *280 test location: "info"
2019/02/04 11:10:55 [debug] 8604#9320: *280 test location: ~ "^(\/v[\d]+\.[\d]+\.[\d]+[\.|-][\d]+)?\/(web-apps\/apps\/api\/documents\/api\.js)$"
2019/02/04 11:10:55 [debug] 8604#9320: *280 test location: ~ "^(\/v[\d]+\.[\d]+\.[\d]+[\.|-][\d]+)?\/(web-apps)(\/.*\.json)$"
2019/02/04 11:10:55 [debug] 8604#9320: *280 test location: ~ "^(\/v[\d]+\.[\d]+\.[\d]+[\.|-][\d]+)?\/(web-apps|sdkjs|sdkjs-plugins|fonts)(\/.*)$"
2019/02/04 11:10:55 [debug] 8604#9320: *280 test location: ~ "^(\/cache\/files.*)(\/.*)"
2019/02/04 11:10:55 [debug] 8604#9320: *280 test location: ~ "^(\/v[\d]+\.[\d]+\.[\d]+[\.|-][\d]+)?(\/doc\/.*)"
2019/02/04 11:10:55 [debug] 8604#9320: *280 test location: ~ "^(\/v[\d]+\.[\d]+\.[\d]+[\.|-][\d]+)?(\/spellchecker)(\/.*)$"
2019/02/04 11:10:55 [debug] 8604#9320: *280 using configuration "/"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http cl:386 max:104857600
2019/02/04 11:10:55 [debug] 8604#9320: *280 rewrite phase: 3
2019/02/04 11:10:55 [debug] 8604#9320: *280 post rewrite phase: 4
2019/02/04 11:10:55 [debug] 8604#9320: *280 generic phase: 5
2019/02/04 11:10:55 [debug] 8604#9320: *280 generic phase: 6
2019/02/04 11:10:55 [debug] 8604#9320: *280 generic phase: 7
2019/02/04 11:10:55 [debug] 8604#9320: *280 access phase: 8
2019/02/04 11:10:55 [debug] 8604#9320: *280 access phase: 9
2019/02/04 11:10:55 [debug] 8604#9320: *280 access phase: 10
2019/02/04 11:10:55 [debug] 8604#9320: *280 post access phase: 11
2019/02/04 11:10:55 [debug] 8604#9320: *280 http request body content length filter
2019/02/04 11:10:55 [debug] 8604#9320: *280 http read client request body
2019/02/04 11:10:55 [debug] 8604#9320: *280 WSARecv: fd:456 rc:-1 0 of 386
2019/02/04 11:10:55 [debug] 8604#9320: *280 WSARecv() not ready (10035: FormatMessage() error:(15105))
2019/02/04 11:10:55 [debug] 8604#9320: *280 http client request body recv -2
2019/02/04 11:10:55 [debug] 8604#9320: *280 http client request body rest 386
2019/02/04 11:10:55 [debug] 8604#9320: *280 event timer add: 456: 60000:3086889329
2019/02/04 11:10:55 [debug] 8604#9320: *280 http finalize request: -4, "/ConvertService.ashx?" a:1, c:2
2019/02/04 11:10:55 [debug] 8604#9320: *280 http request count:2 blk:0
2019/02/04 11:10:55 [debug] 8604#9320: *280 post event 01B4C1A8
2019/02/04 11:10:55 [debug] 8604#9320: *280 delete posted event 01B4C1A8
2019/02/04 11:10:55 [debug] 8604#9320: *280 http run request: "/ConvertService.ashx?"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http read client request body
2019/02/04 11:10:55 [debug] 8604#9320: *280 WSARecv: fd:456 rc:0 386 of 386
2019/02/04 11:10:55 [debug] 8604#9320: *280 http client request body recv 386
2019/02/04 11:10:55 [debug] 8604#9320: *280 http body new buf t:1 f:0 01B7CE2C, pos 01B7CE2C, size: 386 file: 0, size: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 http client request body rest 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 event timer del: 456: 3086889329
2019/02/04 11:10:55 [debug] 8604#9320: *280 http init upstream, client timer: 0
2019/02/04 11:10:55 [debug] 8604#9320: *280 http map started
2019/02/04 11:10:55 [debug] 8604#9320: *280 http map: "" "close"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http map started
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script var: "onlyoffice-osur.univ-rennes1.fr/ds-vpath"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script var: "onlyoffice-osur.univ-rennes1.fr/ds-vpath"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http map: "onlyoffice-osur.univ-rennes1.fr/ds-vpath" "onlyoffice-osur.univ-rennes1.fr/ds-vpath"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http map started
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script var: "https"
2019/02/04 11:10:55 [debug] 8604#9320: *280 malloc: 00414E48:4096
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script var: "https"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http map: "https" "https"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "Host: "
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script var: "localhost:8083"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "
"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: ""
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: ""
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "Connection: "
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script var: "close"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "
"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "X-Forwarded-Host: "
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script var: "onlyoffice-osur.univ-rennes1.fr/ds-vpath"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "
"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "X-Forwarded-Proto: "
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script var: "https"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "
"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "X-Forwarded-For: "
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script var: "129.20.88.149, 129.20.126.25:34616, ::1"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "
"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "Content-Length: "
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script var: "386"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: "
"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: ""
2019/02/04 11:10:55 [debug] 8604#9320: *280 http script copy: ""
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "Content-Type: application/json"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "Max-Forwards: 10"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "X-Forwarded-Server: onlyoffice-osur.univ-rennes1.fr"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "THE-SCHEME: https"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "THE-HOST: onlyoffice-osur.univ-rennes1.fr"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "X-REWRITER-URL: https://onlyoffice-osur.univ-rennes1.fr"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "X-Original-URL: /ds-vpath/ConvertService.ashx"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "X-ARR-SSL: 2048|256|C=FR, O=Universit%C3%A9 de Rennes 1, CN=etoile-frontalufr-47.univ-rennes1.fr|C=FR, O=Universit%C3%A9 de Rennes 1, CN=etoile-frontalufr-47.univ-rennes1.fr"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header: "X-ARR-LOG-ID: 1722afc1-042e-4f92-a4ad-adc5ccd92771"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http proxy header:
"POST /ConvertService.ashx HTTP/1.0
Host: localhost:8083
Connection: close
X-Forwarded-Host: onlyoffice-osur.univ-rennes1.fr/ds-vpath
X-Forwarded-Proto: https
X-Forwarded-For: 129.20.88.149, 129.20.126.25:34616, ::1
Content-Length: 386
Content-Type: application/json
Max-Forwards: 10
X-Forwarded-Server: onlyoffice-osur.univ-rennes1.fr
THE-SCHEME: https
THE-HOST: onlyoffice-osur.univ-rennes1.fr
X-REWRITER-URL: https://onlyoffice-osur.univ-rennes1.fr
X-Original-URL: /ds-vpath/ConvertService.ashx
X-ARR-SSL: 2048|256|C=FR, O=Universit%C3%A9 de Rennes 1, CN=etoile-frontalufr-47.univ-rennes1.fr|C=FR, O=Universit%C3%A9 de Rennes 1, CN=etoile-frontalufr-47.univ-rennes1.fr
X-ARR-LOG-ID: 1722afc1-042e-4f92-a4ad-adc5ccd92771

"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http cleanup add: 00415268
2019/02/04 11:10:55 [debug] 8604#9320: *280 get rr peer, try: 2
2019/02/04 11:10:55 [debug] 8604#9320: *280 get rr peer, current: 01B254BC -1
2019/02/04 11:10:55 [debug] 8604#9320: *280 stream socket 452
2019/02/04 11:10:55 [debug] 8604#9320: *280 connect to 127.0.0.1:8000, fd:452 #283
2019/02/04 11:10:55 [debug] 8604#9320: *280 select add event fd:452 ev:0
2019/02/04 11:10:55 [debug] 8604#9320: *280 select add event fd:452 ev:1
2019/02/04 11:10:55 [debug] 8604#9320: *280 http upstream connect: -2
2019/02/04 11:10:55 [debug] 8604#9320: *280 malloc: 0040DB50:128
2019/02/04 11:10:55 [debug] 8604#9320: *280 event timer add: 452: 60000:3086889329
2019/02/04 11:10:55 [debug] 8604#9320: *280 post event 01B60610
2019/02/04 11:10:55 [debug] 8604#9320: *280 delete posted event 01B60610
2019/02/04 11:10:55 [debug] 8604#9320: *280 http upstream request: "/ConvertService.ashx?"
2019/02/04 11:10:55 [debug] 8604#9320: *280 http upstream send request handler
2019/02/04 11:10:55 [debug] 8604#9320: *280 http upstream send request
2019/02/04 11:10:55 [debug] 8604#9320: *280 http upstream send request body
2019/02/04 11:10:55 [debug] 8604#9320: *280 chain writer buf fl:0 s:740
2019/02/04 11:10:55 [debug] 8604#9320: *280 chain writer buf fl:1 s:386
2019/02/04 11:10:55 [debug] 8604#9320: *280 chain writer in: 00415294
2019/02/04 11:10:55 [debug] 8604#9320: *280 WSASend: fd:452, s:1126
2019/02/04 11:10:55 [debug] 8604#9320: *280 chain writer out: 00000000
2019/02/04 11:10:55 [debug] 8604#9320: *280 event timer del: 452: 3086889329
2019/02/04 11:10:55 [debug] 8604#9320: *280 select del event fd:452 ev:1
2019/02/04 11:10:55 [debug] 8604#9320: *280 event timer add: 452: 60000:3086889345
2019/02/04 11:10:56 [debug] 8604#9320: *280 post event 01B4C608
2019/02/04 11:10:56 [debug] 8604#9320: *280 delete posted event 01B4C608
2019/02/04 11:10:56 [debug] 8604#9320: *280 http upstream request: "/ConvertService.ashx?"
2019/02/04 11:10:56 [debug] 8604#9320: *280 http upstream process header
2019/02/04 11:10:56 [debug] 8604#9320: *280 malloc: 00406A18:4096
2019/02/04 11:10:56 [debug] 8604#9320: *280 WSARecv: fd:452 rc:0 615 of 4096
2019/02/04 11:10:56 [debug] 8604#9320: *280 http proxy status 200 "200 OK"
2019/02/04 11:10:56 [debug] 8604#9320: *280 http proxy header: "X-Powered-By: Express"
2019/02/04 11:10:56 [debug] 8604#9320: *280 http proxy header: "Content-Type: text/xml; charset=UTF-8"
2019/02/04 11:10:56 [debug] 8604#9320: *280 http proxy header: "Content-Length: 414"
2019/02/04 11:10:56 [debug] 8604#9320: *280 http proxy header: "ETag: W/"19e-AhgqdLefY1b6NpNG6731ILRmIUY""
2019/02/04 11:10:56 [debug] 8604#9320: *280 http proxy header: "Date: Mon, 04 Feb 2019 10:10:56 GMT"
2019/02/04 11:10:56 [debug] 8604#9320: *280 http proxy header: "Connection: close"
2019/02/04 11:10:56 [debug] 8604#9320: *280 http proxy header done
2019/02/04 11:10:56 [debug] 8604#9320: *280 HTTP/1.1 200 OK
Server: nginx
Date: Mon, 04 Feb 2019 10:10:56 GMT
Content-Type: text/xml; charset=UTF-8
Content-Length: 414
Connection: keep-alive
Vary: Accept-Encoding
X-Powered-By: Express
ETag: W/"19e-AhgqdLefY1b6NpNG6731ILRmIUY"

2019/02/04 11:10:56 [debug] 8604#9320: *280 write new buf t:1 f:0 00415494, pos 00415494, size: 244 file: 0, size: 0
2019/02/04 11:10:56 [debug] 8604#9320: *280 http write filter: l:0 f:0 s:244
2019/02/04 11:10:56 [debug] 8604#9320: *280 http cacheable: 0
2019/02/04 11:10:56 [debug] 8604#9320: *280 http proxy filter init s:200 h:0 c:0 l:414
2019/02/04 11:10:56 [debug] 8604#9320: *280 http upstream process upstream
2019/02/04 11:10:56 [debug] 8604#9320: *280 pipe read upstream: 0
2019/02/04 11:10:56 [debug] 8604#9320: *280 pipe preread: 414
2019/02/04 11:10:56 [debug] 8604#9320: *280 pipe buf free s:0 t:1 f:0 00406A18, pos 00406AE1, size: 414 file: 0, size: 0
2019/02/04 11:10:56 [debug] 8604#9320: *280 pipe length: 414
2019/02/04 11:10:56 [debug] 8604#9320: *280 input buf #0
2019/02/04 11:10:56 [debug] 8604#9320: *280 pipe write downstream: 1
2019/02/04 11:10:56 [debug] 8604#9320: *280 pipe write downstream flush in
2019/02/04 11:10:56 [debug] 8604#9320: *280 http output filter "/ConvertService.ashx?"
2019/02/04 11:10:56 [debug] 8604#9320: *280 http copy filter: "/ConvertService.ashx?"
2019/02/04 11:10:56 [debug] 8604#9320: *280 http postpone filter "/ConvertService.ashx?" 0041529C
2019/02/04 11:10:56 [debug] 8604#9320: *280 write old buf t:1 f:0 00415494, pos 00415494, size: 244 file: 0, size: 0
2019/02/04 11:10:56 [debug] 8604#9320: *280 write new buf t:1 f:0 00406A18, pos 00406AE1, size: 414 file: 0, size: 0
2019/02/04 11:10:56 [debug] 8604#9320: *280 http write filter: l:0 f:0 s:658
2019/02/04 11:10:56 [debug] 8604#9320: *280 http copy filter: 0 "/ConvertService.ashx?"
2019/02/04 11:10:56 [debug] 8604#9320: *280 pipe write downstream done
2019/02/04 11:10:56 [debug] 8604#9320: *280 event timer del: 452: 3086889345
2019/02/04 11:10:56 [debug] 8604#9320: *280 event timer add: 452: 60000:3086890421
2019/02/04 11:10:56 [debug] 8604#9320: *280 http upstream exit: 00000000
2019/02/04 11:10:56 [debug] 8604#9320: *280 finalize http upstream request: 0
2019/02/04 11:10:56 [debug] 8604#9320: *280 finalize http proxy request
2019/02/04 11:10:56 [debug] 8604#9320: *280 free rr peer 2 0
2019/02/04 11:10:56 [debug] 8604#9320: *280 close http upstream connection: 452
2019/02/04 11:10:56 [debug] 8604#9320: *280 free: 0040DB50, unused: 88
2019/02/04 11:10:56 [debug] 8604#9320: *280 event timer del: 452: 3086890421
2019/02/04 11:10:56 [debug] 8604#9320: *280 select del event fd:452 ev:0
2019/02/04 11:10:56 [debug] 8604#9320: *280 reusable connection: 0
2019/02/04 11:10:56 [debug] 8604#9320: *280 http upstream temp fd: -1
2019/02/04 11:10:56 [debug] 8604#9320: *280 http output filter "/ConvertService.ashx?"
2019/02/04 11:10:56 [debug] 8604#9320: *280 http copy filter: "/ConvertService.ashx?"
2019/02/04 11:10:56 [debug] 8604#9320: *280 http postpone filter "/ConvertService.ashx?" 01AAFC78
2019/02/04 11:10:56 [debug] 8604#9320: *280 write old buf t:1 f:0 00415494, pos 00415494, size: 244 file: 0, size: 0
2019/02/04 11:10:56 [debug] 8604#9320: *280 write old buf t:1 f:0 00406A18, pos 00406AE1, size: 414 file: 0, size: 0
2019/02/04 11:10:56 [debug] 8604#9320: *280 write new buf t:0 f:0 00000000, pos 00000000, size: 0 file: 0, size: 0
2019/02/04 11:10:56 [debug] 8604#9320: *280 http write filter: l:1 f:0 s:658
2019/02/04 11:10:56 [debug] 8604#9320: *280 http write filter limit 0
2019/02/04 11:10:56 [debug] 8604#9320: *280 WSASend: fd:456, s:658
2019/02/04 11:10:56 [debug] 8604#9320: *280 http write filter 00000000
2019/02/04 11:10:56 [debug] 8604#9320: *280 http copy filter: 0 "/ConvertService.ashx?"
2019/02/04 11:10:56 [debug] 8604#9320: *280 http finalize request: 0, "/ConvertService.ashx?" a:1, c:1
2019/02/04 11:10:56 [debug] 8604#9320: *280 set http keepalive handler
2019/02/04 11:10:56 [debug] 8604#9320: *280 http close request
2019/02/04 11:10:56 [debug] 8604#9320: *280 http log handler
2019/02/04 11:10:56 [debug] 8604#9320: *280 free: 00406A18
2019/02/04 11:10:56 [debug] 8604#9320: *280 free: 01B7C078, unused: 3
2019/02/04 11:10:56 [debug] 8604#9320: *280 free: 00414E48, unused: 1808
2019/02/04 11:10:56 [debug] 8604#9320: *280 select del event fd:456 ev:0
2019/02/04 11:10:56 [debug] 8604#9320: *280 free: 01B74CA8
2019/02/04 11:10:56 [debug] 8604#9320: *280 hc free: 00000000 0
2019/02/04 11:10:56 [debug] 8604#9320: *280 hc busy: 00000000 0
2019/02/04 11:10:56 [debug] 8604#9320: *280 reusable connection: 1
2019/02/04 11:10:56 [debug] 8604#9320: *280 event timer add: 456: 65000:3086895421
2019/02/04 11:10:56 [debug] 8604#9320: *280 post event 01B4C1A8
2019/02/04 11:10:56 [debug] 8604#9320: *280 delete posted event 01B4C1A8
2019/02/04 11:10:56 [debug] 8604#9320: *280 http keepalive handler
2019/02/04 11:10:56 [debug] 8604#9320: *280 malloc: 01B74CA8:1024
2019/02/04 11:10:56 [debug] 8604#9320: *280 WSARecv: fd:456 rc:-1 0 of 1024
2019/02/04 11:10:56 [debug] 8604#9320: *280 WSARecv() not ready (10035: FormatMessage() error:(15105))
2019/02/04 11:10:56 [debug] 8604#9320: *280 select add event fd:456 ev:0
2019/02/04 11:10:56 [debug] 8604#9320: *280 free: 01B74CA8
May this help?

otroccaz
Posts: 17
Joined: Wed Jan 16, 2019 4:57 pm

Re: Unable to save settings: an error occurred in the document service

Post by otroccaz » Tue Feb 05, 2019 9:54 am

I'm making some progress! To have more detailed logs for DocumentServer, I need to modify the file \OnlyOffice\DocumentServer\config\log4js\production.json with the line "nodeJS": "ALL". This is what I get in out.log files:

. For docservice:

Code: Select all

[2019-02-05 10:41:11.031] [DEBUG] nodeJS - Start commandFromServer: docId = undefined c = version
[2019-02-05 10:41:11.031] [DEBUG] nodeJS - End commandFromServer: docId = undefined {"error":0,"version":"5.2.2.3"}
[2019-02-05 10:41:11.156] [DEBUG] nodeJS - Start convert request docId = conv_check_1550991489_docx
[2019-02-05 10:41:11.671] [DEBUG] nodeJS - Start receiveTask: docId = conv_check_1550991489_docx {"cmd":{"c":"conv","id":"conv_check_1550991489_docx","format":"docx","url":"https://owncloud-osur.univ-rennes1.fr/apps/onlyoffice/empty?doc=eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJhY3Rpb24iOiJlbXB0eSJ9.4LrHKj8dzh-xsi8rwgjNuz821OYzPJqfvjOCmiwpKJo","title":"empty?doc=eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJhY3Rpb24iOiJlbXB0eSJ9.docx","outputformat":65,"outputpath":"output.docx","codepage":46,"delimiter":4,"embeddedfonts":false,"status_info":0,"nobase64":true}}
[2019-02-05 10:41:11.686] [DEBUG] nodeJS - End receiveTask: docId = conv_check_1550991489_docx
[2019-02-05 10:41:12.326] [DEBUG] nodeJS - End convert request end true url https://onlyoffice-osur.univ-rennes1.fr/ds-vpath/cache/files/conv_check_1550991489_docx/output.docx/empty%3Fdoc%3DeyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJhY3Rpb24iOiJlbXB0eSJ9.docx?md5=ve8srUc2JTodouxj6mKO0Q==&expires=1549360573&disposition=attachment&ooname=output.docx status 0 docId = conv_check_1550991489_docx
. For convert:

Code: Select all

[2019-02-05 10:40:39.410] [DEBUG] nodeJS - [AMQP] connected
[2019-02-05 10:40:39.441] [DEBUG] nodeJS - checkIsSupportOnConflict true
[2019-02-05 10:41:11.187] [DEBUG] nodeJS - Start Task(id=conv_check_1550991489_docx)
[2019-02-05 10:41:11.406] [DEBUG] nodeJS - downloadFile complete filesize=7034 (id=conv_check_1550991489_docx)
[2019-02-05 10:41:11.624] [DEBUG] nodeJS - stdout (id=conv_check_1550991489_docx):
[2019-02-05 10:41:11.624] [DEBUG] nodeJS - stderr (id=conv_check_1550991489_docx):
[2019-02-05 10:41:11.624] [DEBUG] nodeJS - ExitCode (code=0;signal=null;error:0;id=conv_check_1550991489_docx)
[2019-02-05 10:41:11.655] [DEBUG] nodeJS - processUploadToStorage complete(id=conv_check_1550991489_docx)
[2019-02-05 10:41:11.655] [DEBUG] nodeJS - output (data={"cmd":{"c":"conv","id":"conv_check_1550991489_docx","format":"docx","url":"https://owncloud-osur.univ-rennes1.fr/apps/onlyoffice/empty?doc=eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJhY3Rpb24iOiJlbXB0eSJ9.4LrHKj8dzh-xsi8rwgjNuz821OYzPJqfvjOCmiwpKJo","title":"empty?doc=eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJhY3Rpb24iOiJlbXB0eSJ9.docx","outputformat":65,"outputpath":"output.docx","codepage":46,"delimiter":4,"embeddedfonts":false,"status_info":0,"nobase64":true}};id=conv_check_1550991489_docx)
[2019-02-05 10:41:11.655] [DEBUG] nodeJS - postProcess (id=conv_check_1550991489_docx)
[2019-02-05 10:41:11.655] [DEBUG] nodeJS - deleteFolderRecursive (id=conv_check_1550991489_docx)
But nothing in error.log files.

Carl
Posts: 160
Joined: Thu Apr 12, 2018 10:00 am

Re: Unable to save settings: an error occurred in the document service

Post by Carl » Tue Feb 05, 2019 11:31 am

Hello,

Logging level "ALL" provides extended logs, "WARN" level should be enough. Usually records about events like this are in out.log, please switch the logging level to WARN, restart all Document Server services and try to save the settings anew. Try to look for error messages in converter/out.log and docservice/out.log.

otroccaz
Posts: 17
Joined: Wed Jan 16, 2019 4:57 pm

Re: Unable to save settings: an error occurred in the document service

Post by otroccaz » Tue Feb 05, 2019 12:14 pm

Hello Carl!

Thanks for your reply!
This is what I get:

For converter/out.log:

Code: Select all

[2019-02-05 13:02:35.620] [WARN] nodeJS - update cluster with 1 workers
[2019-02-05 13:02:35.636] [WARN] nodeJS - worker 38508 started.
[2019-02-05 13:02:35.636] [WARN] nodeJS - update cluster with 1 workers
For docservice/out.log:

Code: Select all

[2019-02-05 13:02:42.374] [WARN] nodeJS - Plugins watch exception (https://nodejs.org/docs/latest/api/fs.html#fs_availability).
[2019-02-05 13:02:42.406] [WARN] nodeJS - update cluster with 1 workers
[2019-02-05 13:02:42.421] [WARN] nodeJS - worker 38532 started.
[2019-02-05 13:02:42.421] [WARN] nodeJS - update cluster with 1 workers
[2019-02-05 13:02:43.920] [WARN] nodeJS - Express server starting...
[2019-02-05 13:02:45.262] [WARN] nodeJS - Express server listening on port 8000 in production-windows mode
Do you think that the error could come from that "nodeJS - Plugins watch exception"? But it's just a WARN not an ERROR.

Carl
Posts: 160
Joined: Thu Apr 12, 2018 10:00 am

Re: Unable to save settings: an error occurred in the document service

Post by Carl » Tue Feb 05, 2019 1:35 pm

Do you think that the error could come from that "nodeJS - Plugins watch exception"? But it's just a WARN not an ERROR.
These are not errors.

Please provide some additional information on your ONLYOFFICE installation.

1. Exact OS of the server where it is installed.
2. Versions of ONLYOFFICE components (Document Server, Community Server).
3. Does the document editing function correctly on your portal.
4. Have you installed Community Server and Document Server separately or as ONLYOFFICE Community Edition?
5. Version of Owncloud and ONLYOFFICE connector installed.
6. Try to stop all Document Server services, remove logs from converter and docservice folders, start the services again and save the settings in Owncloud. Send us new converter and docservice logs.

otroccaz
Posts: 17
Joined: Wed Jan 16, 2019 4:57 pm

Re: Unable to save settings: an error occurred in the document service

Post by otroccaz » Tue Feb 05, 2019 2:25 pm

Thank you very much for your time! Here's the information:

1. Windows Server 2008 R2 Standard 64 bits
2. Community Edition 18.10.255 > Document Server 5.2.2.3 - Community Server 9.6.2 (? not easy to find their versions because the installation is done via Community Edition)
3. Yes, the portal is functional
4. As ONLYOFFICE Community Edition
5. ownCloud 10.0.10.4 - Onlyoffice connector 2.1.3
6. Here are the logs:

Converter log:

Code: Select all

[2019-02-05 15:12:34.167] [WARN] nodeJS - update cluster with 1 workers
[2019-02-05 15:12:34.198] [WARN] nodeJS - worker 6036 started.
[2019-02-05 15:12:34.198] [WARN] nodeJS - update cluster with 1 workers
Docservice log :

Code: Select all

[2019-02-05 15:12:28.660] [WARN] nodeJS - Plugins watch exception (https://nodejs.org/docs/latest/api/fs.html#fs_availability).
[2019-02-05 15:12:28.692] [WARN] nodeJS - update cluster with 1 workers
[2019-02-05 15:12:28.692] [WARN] nodeJS - worker 7932 started.
[2019-02-05 15:12:28.692] [WARN] nodeJS - update cluster with 1 workers
[2019-02-05 15:12:30.158] [WARN] nodeJS - Express server starting...
[2019-02-05 15:12:31.500] [WARN] nodeJS - Express server listening on port 8000 in production-windows mode

Carl
Posts: 160
Joined: Thu Apr 12, 2018 10:00 am

Re: Unable to save settings: an error occurred in the document service

Post by Carl » Wed Feb 06, 2019 5:25 am

First of all, I would recommend you to update the Document Server to the current version (5.2.8, we have just released it). Let me know if the issue persists.

otroccaz
Posts: 17
Joined: Wed Jan 16, 2019 4:57 pm

Re: Unable to save settings: an error occurred in the document service

Post by otroccaz » Wed Feb 06, 2019 8:53 am

Hello Carl!
I updated the Document Server and had to change the "community server address for requests from the document service" to "http://onlyoffice-osur.univ-rennes1.fr/" (no https) of the document service location because otherwise the portal did not work (the converter out.log file showed a self signed certificate error) .
However, when I try to save the configuration on ownCloud, I always get the same error.
Couldn't the modification I had to make for the portal mean that the error is due to a certificate problem (even if no trace appears in the logs)?

otroccaz
Posts: 17
Joined: Wed Jan 16, 2019 4:57 pm

Re: Unable to save settings: an error occurred in the document service

Post by otroccaz » Wed Feb 06, 2019 10:27 am

I found it!
On owncloud, in the advanced server settings, for the document editing service address for internal server requests, I put http://IP-Onlyoffice-server:8083/ ... and I was able to save the settings!
Thank you very much for your time.

Post Reply