Code: Select all
404 error, in :
Startup1_1_all.js.zgz?v=141215153642:27247 GET https://tablon.oopre.euskaltel.es/service/proxy?target=https%3A%2F%2Fxmpp.oopre.euskaltel.es%2Fmiddleware_lib.js&_=1465480377806 404 (Not Found)
Our zimbra environmet is multi-server and multi-domain.
Certificate is from a unknow CA , own Certificate autority , CA root and intermediate have been installed in servers ( zimbra and ztalk , in O.S level ).
IN mailbox.log I get:
Code: Select all
2016-06-09 11:27:58,053 INFO [qtp509886383-1480:http://172.18.167.37:8080/service/proxy?target=https%3A%2F%2Fxmpp.oopre.euskaltel.es%2Fmiddleware_lib.js&_=1465464530126] [] zimlet - exception while proxying https://xmpp.oopre.euskaltel.es/middleware_lib.js
org.apache.commons.httpclient.ProtocolException: The server xmpp.oopre.euskaltel.es failed to respond with a valid HTTP response
at org.apache.commons.httpclient.HttpMethodBase.readStatusLine(HttpMethodBase.java:1987)
Code: Select all
016/06/09 15:52:31 [debug] 10823#0: *389 http request line: "GET /service/proxy?target=https%3A%2F%2Fxmpp.oopre.euskaltel.es%2Fmiddleware_lib.js&_=1465480377806 HTTP/1.1"
2016/06/09 15:52:31 [debug] 10823#0: *389 http uri: "/service/proxy"
2016/06/09 15:52:31 [debug] 10823#0: *389 http args: "target=https%3A%2F%2Fxmpp.oopre.euskaltel.es%2Fmiddleware_lib.js&_=1465480377806"
2016/06/09 15:52:31 [debug] 10823#0: *389 http exten: ""
2016/06/09 15:52:31 [debug] 10823#0: *389 http process request header line
2016/06/09 15:52:31 [debug] 10823#0: *389 http header: "Host: tablon.oopre.euskaltel.es"
2016/06/09 15:52:31 [debug] 10823#0: *389 http header: "Connection: keep-alive"
2016/06/09 15:52:31 [debug] 10823#0: *389 http header: "Accept: text/javascript, application/javascript, application/ecmascript, application/x-ecmascript, */*; q=0.01"
2016/06/09 15:52:31 [debug] 10823#0: *389 http header: "X-Requested-With: XMLHttpRequest"
2016/06/09 15:52:31 [debug] 10823#0: *389 http header: "User-Agent: Mozilla/5.0 (Windows NT 5.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/49.0.2623.112 Safari/537.36"
2016/06/09 15:52:31 [debug] 10823#0: *389 http header: "Referer: https://tablon.oopre.euskaltel.es/"
2016/06/09 15:52:31 [debug] 10823#0: *389 http header: "Accept-Encoding: gzip, deflate, sdch"
2016/06/09 15:52:31 [debug] 10823#0: *389 http header: "Accept-Language: es-ES,es;q=0.8"
2016/06/09 15:52:31 [debug] 10823#0: *389 http header: "Cookie: _ga=GA1.2.1307744682.1444394039; ZM_TEST=true; ZM_AUTH_TOKEN=0_ef9b51306b494b751639c63bc8a44c810c7e465b_69643d33363a62646139646662662d323065642d343537622d396663642d3866616361653063646330623b6578703d31333a313436353635333130393537393b76763d313a323b747970653d363a7a696d6272613b7469643d393a3332383836363034363b76657273696f6e3d31333a382e362e305f47415f313135333b637372663d313a313b; JSESSIONID=1r4s5q9tgljuzvqt9i779fugg"
2016/06/09 15:52:31 [debug] 10823#0: *389 http header done
2016/06/09 15:52:31 [debug] 10823#0: *389 event timer del: 20: 1465480424271
2016/06/09 15:52:31 [debug] 10823#0: *389 rewrite phase: 0
2016/06/09 15:52:31 [debug] 10823#0: *389 http script value: "http://zimbra_login"
2016/06/09 15:52:31 [debug] 10823#0: *389 http script set $login_upstream
2016/06/09 15:52:31 [debug] 10823#0: *389 http script var
2016/06/09 15:52:31 [debug] 10823#0: *389 http script var: "_ga=GA1.2.1307744682.1444394039; ZM_TEST=true; ZM_AUTH_TOKEN=0_ef9b51306b494b751639c63bc8a44c810c7e465b_69643d33363a62646139646662662d323065642d343537622d396663642d3866616361653063646330623b6578703d31333a313436353635333130393537393b76763d313a323b747970653d363a7a696d6272613b7469643d393a3332383836363034363b76657273696f6e3d31333a382e362e305f47415f313135333b637372663d313a313b; JSESSIONID=1r4s5q9tgljuzvqt9i779fugg"
2016/06/09 15:52:31 [debug] 10823#0: *389 http script regex: "ZM_AUTH_TOKEN="
2016/06/09 15:52:31 [notice] 10823#0: *389 "ZM_AUTH_TOKEN=" matches "_ga=GA1.2.1307744682.1444394039; ZM_TEST=true; ZM_AUTH_TOKEN=0_ef9b51306b494b751639c63bc8a44c810c7e465b_69643d33363a62646139646662662d323065642d343537622d396663642d3866616361653063646330623b6578703d31333a313436353635333130393537393b76763d313a323b747970653d363a7a696d6272613b7469643d393a3332383836363034363b76657273696f6e3d31333a382e362e305f47415f313135333b637372663d313a313b; JSESSIONID=1r4s5q9tgljuzvqt9i779fugg", client: 172.18.147.250:3492, server: tablon.oopre.euskaltel.es, request: "GET /service/proxy?target=https%3A%2F%2Fxmpp.oopre.euskaltel.es%2Fmiddleware_lib.js&_=1465480377806 HTTP/1.1", host: "tablon.oopre.euskaltel.es", referrer: "https://tablon.oopre.euskaltel.es/"
2016/06/09 15:52:31 [debug] 10823#0: *389 http script if
2016/06/09 15:52:31 [debug] 10823#0: *389 http script value: "http://zimbra_webclient"
2016/06/09 15:52:31 [debug] 10823#0: *389 http script set $login_upstream
2016/06/09 15:52:31 [debug] 10823#0: *389 test location: "/"
2016/06/09 15:52:31 [debug] 10823#0: *389 test location: "nginx_status"
2016/06/09 15:52:31 [debug] 10823#0: *389 test location: "service/soap/WaitSetRequest"
2016/06/09 15:52:31 [debug] 10823#0: *389 test location: "service/soap/NoOpRequest"
2016/06/09 15:52:31 [debug] 10823#0: *389 test location: ~ "^/ews/Exchange.asmx"
2016/06/09 15:52:31 [debug] 10823#0: *389 test location: ~ "/(service|principals|dav|\.well-known|home|octopus|shf|user|certauth|spnegoauth|(zimbra/home)|(zimbra/user))/"
2016/06/09 15:52:31 [debug] 10823#0: *389 using configuration "/(service|principals|dav|\.well-known|home|octopus|shf|user|certauth|spnegoauth|(zimbra/home)|(zimbra/user))/"
2016/06/09 15:52:31 [debug] 10823#0: *389 http cl:-1 max:0
2016/06/09 15:52:31 [debug] 10823#0: *389 rewrite phase: 2
2016/06/09 15:52:31 [debug] 10823#0: *389 http script value: "8080"
2016/06/09 15:52:31 [debug] 10823#0: *389 http script set $mailhostport
2016/06/09 15:52:31 [debug] 10823#0: *389 http script complex value
2016/06/09 15:52:31 [debug] 10823#0: *389 http script var: "tablon.oopre.euskaltel.es"
2016/06/09 15:52:31 [debug] 10823#0: *389 http script set $relhost
2016/06/09 15:52:31 [debug] 10823#0: *389 http script var
2016/06/09 15:52:31 [debug] 10823#0: *389 http script var: "8080"
2016/06/09 15:52:31 [debug] 10823#0: *389 http script value: "80"
2016/06/09 15:52:31 [debug] 10823#0: *389 http script not equal
2016/06/09 15:52:31 [debug] 10823#0: *389 http script if
2016/06/09 15:52:31 [debug] 10823#0: *389 http script complex value
2016/06/09 15:52:31 [debug] 10823#0: *389 http script var: "tablon.oopre.euskaltel.es"
2016/06/09 15:52:31 [debug] 10823#0: *389 http script copy: ":"
2016/06/09 15:52:31 [debug] 10823#0: *389 http script var: "8080"
2016/06/09 15:52:31 [debug] 10823#0: *389 http script set $relhost
2016/06/09 15:52:31 [debug] 10823#0: *389 http script complex value
2016/06/09 15:52:31 [debug] 10823#0: *389 http script var: "tablon.oopre.euskaltel.es"
2016/06/09 15:52:31 [debug] 10823#0: *389 http script set $virtual_host
2016/06/09 15:52:31 [debug] 10823#0: *389 http script var
2016/06/09 15:52:31 [debug] 10823#0: *389 http script var: "tablon.oopre.euskaltel.es"
2016/06/09 15:52:31 [debug] 10823#0: *389 http script value: ""
2016/06/09 15:52:31 [debug] 10823#0: *389 http script equal
2016/06/09 15:52:31 [debug] 10823#0: *389 http script equal: no
2016/06/09 15:52:31 [debug] 10823#0: *389 http script if
2016/06/09 15:52:31 [debug] 10823#0: *389 http script if: false
2016/06/09 15:52:31 [debug] 10823#0: *389 post rewrite phase: 3
2016/06/09 15:52:31 [debug] 10823#0: *389 generic phase: 4
2016/06/09 15:52:31 [debug] 10823#0: *389 generic phase: 5
2016/06/09 15:52:31 [debug] 10823#0: *389 access phase: 6
2016/06/09 15:52:31 [debug] 10823#0: *389 access phase: 7
2016/06/09 15:52:31 [debug] 10823#0: *389 access phase: 8
2016/06/09 15:52:31 [debug] 10823#0: *389 access phase: 9
2016/06/09 15:52:31 [debug] 10823#0: *389 post access phase: 10
2016/06/09 15:52:31 [debug] 10823#0: *389 posix_memalign: 00000000023758B0:4096 @16
2016/06/09 15:52:31 [debug] 10823#0: *389 http init upstream, client timer: 0
2016/06/09 15:52:31 [debug] 10823#0: *389 http script copy: "X-Forwarded-For: "
2016/06/09 15:52:31 [debug] 10823#0: *389 http script var: "172.18.147.250"
2016/06/09 15:52:31 [debug] 10823#0: *389 http script copy: "^M
"
2016/06/09 15:52:31 [debug] 10823#0: *389 http script copy: "Host: "
2016/06/09 15:52:31 [debug] 10823#0: *389 http script var: "tablon.oopre.euskaltel.es"
2016/06/09 15:52:31 [debug] 10823#0: *389 http script copy: "^M
"
2016/06/09 15:52:31 [debug] 10823#0: *389 http script copy: "Connection: close^M
"
2016/06/09 15:52:31 [debug] 10823#0: *389 http proxy header: "Accept: text/javascript, application/javascript, application/ecmascript, application/x-ecmascript, */*; q=0.01"
2016/06/09 15:52:31 [debug] 10823#0: *389 http proxy header: "X-Requested-With: XMLHttpRequest"
2016/06/09 15:52:31 [debug] 10823#0: *389 http proxy header: "User-Agent: Mozilla/5.0 (Windows NT 5.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/49.0.2623.112 Safari/537.36"
2016/06/09 15:52:31 [debug] 10823#0: *389 http proxy header: "Referer: https://tablon.oopre.euskaltel.es/"
2016/06/09 15:52:31 [debug] 10823#0: *389 http proxy header: "Accept-Encoding: gzip, deflate, sdch"
2016/06/09 15:52:31 [debug] 10823#0: *389 http proxy header: "Accept-Language: es-ES,es;q=0.8"
2016/06/09 15:52:31 [debug] 10823#0: *389 http proxy header: "Cookie: _ga=GA1.2.1307744682.1444394039; ZM_TEST=true; ZM_AUTH_TOKEN=0_ef9b51306b494b751639c63bc8a44c810c7e465b_69643d33363a62646139646662662d323065642d343537622d396663642d3866616361653063646330623b6578703d31333a313436353635333130393537393b76763d313a323b747970653d363a7a696d6272613b7469643d393a3332383836363034363b76657273696f6e3d31333a382e362e305f47415f313135333b637372663d313a313b; JSESSIONID=1r4s5q9tgljuzvqt9i779fugg"
2016/06/09 15:52:31 [debug] 10823#0: *389 http proxy header:
"GET /service/proxy?target=https%3A%2F%2Fxmpp.oopre.euskaltel.es%2Fmiddleware_lib.js&_=1465480377806 HTTP/1.0^M
X-Forwarded-For: 172.18.147.250^M
Host: tablon.oopre.euskaltel.es^M
Connection: close^M
Accept: text/javascript, application/javascript, application/ecmascript, application/x-ecmascript, */*; q=0.01^M
X-Requested-With: XMLHttpRequest^M
User-Agent: Mozilla/5.0 (Windows NT 5.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/49.0.2623.112 Safari/537.36^M
Referer: https://tablon.oopre.euskaltel.es/^M
Accept-Encoding: gzip, deflate, sdch^M
Accept-Language: es-ES,es;q=0.8^M
Cookie: _ga=GA1.2.1307744682.1444394039; ZM_TEST=true; ZM_AUTH_TOKEN=0_ef9b51306b494b751639c63bc8a44c810c7e465b_69643d33363a62646139646662662d323065642d343537622d396663642d3866616361653063646330623b6578703d31333a313436353635333130393537393b76763d313a323b747970653d363a7a696d6272613b7469643d393a3332383836363034363b76657273696f6e3d31333a382e362e305f47415f313135333b637372663d313a313b; JSESSIONID=1r4s5q9tgljuzvqt9i779fugg^M
^M
"
2016/06/09 15:52:31 [debug] 10823#0: *389 http cleanup add: 0000000002376010
2016/06/09 15:52:31 [debug] 10823#0: *389 zmauth: lookup route for web proxy
2016/06/09 15:52:31 [debug] 10823#0: *389 zmauth: examining uri:/service/proxy for REST
2016/06/09 15:52:31 [debug] 10823#0: *389 zmauth: examining uri:/service/proxy for ActiveSync
2016/06/09 15:52:31 [debug] 10823#0: *389 zmauth: examining uri:/service/proxy for EWS
2016/06/09 15:52:31 [debug] 10823#0: *389 zmauth: examining uri:/service/proxy for caldav
2016/06/09 15:52:31 [debug] 10823#0: *389 zmauth: search for ZM_AUTH_TOKEN
2016/06/09 15:52:31 [debug] 10823#0: *389 zmauth: examining cookie value:_ga=GA1.2.1307744682.1444394039; ZM_TEST=true; ZM_AUTH_TOKEN=0_ef9b51306b494b751639c63bc8a44c810c7e465b_69643d33363a62646139646662662d323065642d343537622d396663642d3866616361653063646330623b6578703d31333a313436353635333130393537393b76763d313a323b747970653d363a7a696d6272613b7469643d393a3332383836363034363b76657273696f6e3d31333a382e362e305f47415f313135333b637372663d313a313b; JSESSIONID=1r4s5q9tgljuzvqt9i779fugg
2016/06/09 15:52:31 [debug] 10823#0: *389 zmauth: found ZM_AUTH_TOKEN:0_ef9b51306b494b751639c63bc8a44c810c7e465b_69643d33363a62646139646662662d323065642d343537622d396663642d3866616361653063646330623b6578703d31333a313436353635333130393537393b76763d313a323b747970653d363a7a696d6272613b7469643d393a3332383836363034363b76657273696f6e3d31333a382e362e305f47415f313135333b637372663d313a313b
2016/06/09 15:52:31 [debug] 10823#0: *389 zmauth: decoded(auth-token(#2)): id=36:bda9dfbf-20ed-457b-9fcd-8facae0cdc0b;exp=13:1465653109579;vv=1:2;type=6:zimbra;tid=9:328866046;version=13:8.6.0_GA_1153;csrf=1:1;
2016/06/09 15:52:31 [debug] 10823#0: *389 zmauth: auth-token(field=id,len=36,value=bda9dfbf-20ed-457b-9fcd-8facae0cdc0b)
2016/06/09 15:52:31 [debug] 10823#0: *389 zmauth: got id:bda9dfbf-20ed-457b-9fcd-8facae0cdc0b from ZM_AUTH_TOKEN
2016/06/09 15:52:31 [debug] 10823#0: *389 zmauth: routing by ZM_AUTH_TOKEN
2016/06/09 15:52:31 [debug] 10823#0: *389 zmauth: search for ZM_AUTH_TOKEN
2016/06/09 15:52:31 [debug] 10823#0: *389 zmauth: examining cookie value:_ga=GA1.2.1307744682.1444394039; ZM_TEST=true; ZM_AUTH_TOKEN=0_ef9b51306b494b751639c63bc8a44c810c7e465b_69643d33363a62646139646662662d323065642d343537622d396663642d3866616361653063646330623b6578703d31333a313436353635333130393537393b76763d313a323b747970653d363a7a696d6272613b7469643d393a3332383836363034363b76657273696f6e3d31333a382e362e305f47415f313135333b637372663d313a313b; JSESSIONID=1r4s5q9tgljuzvqt9i779fugg
2016/06/09 15:52:31 [debug] 10823#0: *389 zmauth: found ZM_AUTH_TOKEN:0_ef9b51306b494b751639c63bc8a44c810c7e465b_69643d33363a62646139646662662d323065642d343537622d396663642d3866616361653063646330623b6578703d31333a313436353635333130393537393b76763d313a323b747970653d363a7a696d6272613b7469643d393a3332383836363034363b76657273696f6e3d31333a382e362e305f47415f313135333b637372663d313a313b
2016/06/09 15:52:31 [debug] 10823#0: *389 zmauth: decoded(auth-token(#2)): id=36:bda9dfbf-20ed-457b-9fcd-8facae0cdc0b;exp=13:1465653109579;vv=1:2;type=6:zimbra;tid=9:328866046;version=13:8.6.0_GA_1153;csrf=1:1;
2016/06/09 15:52:31 [debug] 10823#0: *389 zmauth: auth-token(field=version,len=13,value=8.6.0_GA_1153)
2016/06/09 15:52:31 [debug] 10823#0: *389 zmauth: got version:8.6.0_GA_1153 from ZM_AUTH_TOKEN
2016/06/09 15:52:31 [debug] 10823#0: *389 zmauth: route lookup required to proxy request
2016/06/09 15:52:31 [debug] 10823#0: *389 posix_memalign: 00000000023768C0:2048 @16
2016/06/09 15:52:31 [debug] 10823#0: *389 http cleanup add: 0000000002376218
2016/06/09 15:52:31 [debug] 10823#0: *389 posting memcache request to cache server #0
2016/06/09 15:52:31 [debug] 10823#0: *389 posix_memalign: 00000000023770D0:1024 @16
2016/06/09 15:52:31 [debug] 10823#0: *389 generate pdu get route:proto=http;id=bda9dfbf-20ed-457b-9fcd-8facae0cdc0b^M
2016/06/09 15:52:31 [debug] 10823#0: send: fd:16 62 of 62
2016/06/09 15:52:31 [debug] 10823#0: event timer add: 16: 3000:1465480354542
2016/06/09 15:52:31 [debug] 10823#0: *389 posted request(0000000002377160) on server #0
2016/06/09 15:52:31 [debug] 10823#0: *389 http finalize request: -4, "/service/proxy?target=https%3A%2F%2Fxmpp.oopre.euskaltel.es%2Fmiddleware_lib.js&_=1465480377806" a:1, c:2
2016/06/09 15:52:31 [debug] 10823#0: *389 http request count:2 blk:0
2016/06/09 15:52:31 [debug] 10823#0: *389 http run request: "/service/proxy?target=https%3A%2F%2Fxmpp.oopre.euskaltel.es%2Fmiddleware_lib.js&_=1465480377806"
2016/06/09 15:52:31 [debug] 10823#0: *389 http upstream check client, write event:1, "/service/proxy"
2016/06/09 15:52:31 [debug] 10823#0: *389 http upstream recv(): -1 (11: Resource temporarily unavailable)
2016/06/09 15:52:31 [debug] 10823#0: timer delta: 48
2016/06/09 15:52:31 [debug] 10823#0: posted events 0000000000000000
2016/06/09 15:52:31 [debug] 10823#0: worker cycle
2016/06/09 15:52:31 [debug] 10823#0: accept mutex lock failed: 0
2016/06/09 15:52:31 [debug] 10823#0: epoll timer: 500
2016/06/09 15:52:31 [debug] 10823#0: epoll: fd:16 ev:0005 d:00007F8015788610
2016/06/09 15:52:31 [debug] 10823#0: memcached read event:172.18.167.38:11211
2016/06/09 15:52:31 [debug] 10823#0: recv: fd:16 94 of 4002
2016/06/09 15:52:31 [debug] 10823#0: event timer del: 16: 1465480354542
2016/06/09 15:52:31 [debug] 10823#0: memcache proto-handler consumed:94,rc:0
2016/06/09 15:52:31 [debug] 10823#0: *389 zm lookup: fetch cached route:172.18.167.37:8080 for user:bda9dfbf-20ed-457b-9fcd-8facae0cdc0b
2016/06/09 15:52:31 [debug] 10823#0: *389 free: 00000000023768C0, unused: 1296
2016/06/09 15:52:31 [debug] 10823#0: *389 zmauth: prepare upstream connection, try: 2
2016/06/09 15:52:31 [debug] 10823#0: *389 zmauth: version in zm_auth_token: 8.6.0_GA_1153
2016/06/09 15:52:31 [debug] 10823#0: *389 zmauth: upstream server 0 is returned by zmlookup
2016/06/09 15:52:31 [debug] 10823#0: *389 socket 22
2016/06/09 15:52:31 [debug] 10823#0: *389 epoll add connection: fd:22 ev:80000005
2016/06/09 15:52:31 [debug] 10823#0: *389 connect to 172.18.167.37:8080, fd:22 #406
2016/06/09 15:52:31 [debug] 10823#0: *389 http upstream connect: -2
2016/06/09 15:52:31 [debug] 10823#0: *389 posix_memalign: 000000000246D540:128 @16
2016/06/09 15:52:31 [debug] 10823#0: *389 event timer add: 22: 25000:1465480376544
2016/06/09 15:52:31 [debug] 10823#0: *389 free: 00000000023770D0, unused: 782
2016/06/09 15:52:31 [debug] 10823#0: dummy memcache write-event handler
2016/06/09 15:52:31 [debug] 10823#0: timer delta: 2
2016/06/09 15:52:31 [debug] 10823#0: posted events 0000000000000000
2016/06/09 15:52:31 [debug] 10823#0: worker cycle
2016/06/09 15:52:31 [debug] 10823#0: accept mutex lock failed: 0
2016/06/09 15:52:31 [debug] 10823#0: epoll timer: 500
2016/06/09 15:52:31 [debug] 10823#0: epoll: fd:22 ev:0004 d:00007F8015788910
2016/06/09 15:52:31 [debug] 10823#0: *389 http upstream request: "/service/proxy?target=https%3A%2F%2Fxmpp.oopre.euskaltel.es%2Fmiddleware_lib.js&_=1465480377806"
2016/06/09 15:52:31 [debug] 10823#0: *389 http upstream send request handler
2016/06/09 15:52:31 [debug] 10823#0: *389 http upstream send request
2016/06/09 15:52:31 [debug] 10823#0: *389 chain writer buf fl:1 s:997
2016/06/09 15:52:31 [debug] 10823#0: *389 chain writer in: 0000000002376268
2016/06/09 15:52:31 [debug] 10823#0: *389 writev: 997
2016/06/09 15:52:31 [debug] 10823#0: *389 chain writer out: 0000000000000000
2016/06/09 15:52:31 [debug] 10823#0: *389 event timer del: 22: 1465480376544
2016/06/09 15:52:31 [debug] 10823#0: *389 event timer add: 22: 60000:1465480411544
2016/06/09 15:52:31 [debug] 10823#0: timer delta: 0
2016/06/09 15:52:31 [debug] 10823#0: posted events 0000000000000000
2016/06/09 15:52:31 [debug] 10823#0: worker cycle
2016/06/09 15:52:31 [debug] 10823#0: accept mutex lock failed: 0
2016/06/09 15:52:31 [debug] 10823#0: epoll timer: 500
2016/06/09 15:52:31 [debug] 10825#0: epoll: fd:12 ev:0001 d:00007F8015788490
2016/06/09 15:52:31 [debug] 10825#0: post event 00007F8015683280
2016/06/09 15:52:31 [debug] 10825#0: timer delta: 4012
2016/06/09 15:52:31 [debug] 10825#0: posted event 00007F8015683280
2016/06/09 15:52:31 [debug] 10825#0: delete posted event 00007F8015683280
2016/06/09 15:52:31 [debug] 10825#0: accept on 172.18.167.38:443, ready: 0
2016/06/09 15:52:31 [debug] 10825#0: posix_memalign: 0000000002484E10:256 @16
2016/06/09 15:52:31 [debug] 10825#0: *407 accept: 172.18.167.37 fd:16
2016/06/09 15:52:31 [debug] 10825#0: *407 event timer add: 16: 60000:1465480411560
2016/06/09 15:52:31 [debug] 10825#0: *407 epoll add event: fd:16 op:1 ev:80000001
2016/06/09 15:52:31 [debug] 10825#0: posted event 0000000000000000
2016/06/09 15:52:31 [debug] 10825#0: posted events 0000000000000000
2016/06/09 15:52:31 [debug] 10825#0: worker cycle
2016/06/09 15:52:31 [debug] 10825#0: accept mutex locked
2016/06/09 15:52:31 [debug] 10825#0: epoll timer: 60000
2016/06/09 15:52:31 [debug] 10825#0: epoll: fd:16 ev:0001 d:00007F8015788791
2016/06/09 15:52:31 [debug] 10825#0: *407 post event 00007F8015683420
2016/06/09 15:52:31 [debug] 10825#0: timer delta: 3
2016/06/09 15:52:31 [debug] 10825#0: posted events 00007F8015683420
2016/06/09 15:52:31 [debug] 10825#0: posted event 00007F8015683420
2016/06/09 15:52:31 [debug] 10825#0: *407 delete posted event 00007F8015683420
2016/06/09 15:52:31 [debug] 10825#0: *407 malloc: 000000000237B020:1256
2016/06/09 15:52:31 [debug] 10825#0: *407 posix_memalign: 000000000243E380:256 @16
2016/06/09 15:52:31 [debug] 10825#0: *407 malloc: 0000000002460100:1024
2016/06/09 15:52:31 [debug] 10825#0: *407 posix_memalign: 000000000244FC90:4096 @16
2016/06/09 15:52:31 [debug] 10825#0: *407 http check ssl handshake
2016/06/09 15:52:31 [debug] 10825#0: *407 plain http
2016/06/09 15:52:31 [debug] 10825#0: *407 http process request line
2016/06/09 15:52:31 [debug] 10825#0: *407 recv: fd:16 153 of 1024
2016/06/09 15:52:31 [info] 10825#0: *407 client sent invalid request while reading client request line, client: 172.18.167.37:56372, server: oo1prxpre.euskaltel.es.default, request: "CONNECT xmpp.oopre.euskaltel.es:443 HTTP/1.1"
2016/06/09 15:52:31 [debug] 10825#0: *407 http finalize request: 400, "?" a:1, c:1
2016/06/09 15:52:31 [debug] 10825#0: *407 http finalize request: 400, "?" a:1, c:1
2016/06/09 15:52:31 [debug] 10825#0: *407 event timer del: 16: 1465480411560
2016/06/09 15:52:31 [debug] 10825#0: *407 http special response: 400, "?"
2016/06/09 15:52:31 [debug] 10825#0: *407 http set discard body
2016/06/09 15:52:31 [debug] 10825#0: *407 http output filter "?"
2016/06/09 15:52:31 [debug] 10825#0: *407 http copy filter: "?"
2016/06/09 15:52:31 [debug] 10825#0: *407 http postpone filter "?" 0000000002450460
2016/06/09 15:52:31 [debug] 10825#0: *407 write new buf t:0 f:0 0000000000000000, pos 000000000070D020, size: 120 file: 0, size: 0
2016/06/09 15:52:31 [debug] 10825#0: *407 http write filter: l:1 f:0 s:166
2016/06/09 15:52:31 [debug] 10825#0: *407 http write filter limit 0
2016/06/09 15:52:31 [debug] 10825#0: *407 writev: 166
2016/06/09 15:52:31 [debug] 10825#0: *407 http write filter 0000000000000000
2016/06/09 15:52:31 [debug] 10825#0: *407 http copy filter: 0 "?"
2016/06/09 15:52:31 [debug] 10825#0: *407 http finalize request: 0, "?" a:1, c:1
2016/06/09 15:52:31 [debug] 10825#0: *407 event timer add: 16: 5000:1465480356563
2016/06/09 15:52:31 [debug] 10825#0: *407 http lingering close handler
2016/06/09 15:52:31 [debug] 10825#0: *407 recv: fd:16 -1 of 4096
2016/06/09 15:52:31 [debug] 10825#0: *407 recv() not ready (11: Resource temporarily unavailable)
2016/06/09 15:52:31 [debug] 10825#0: *407 lingering read: -2
2016/06/09 15:52:31 [debug] 10825#0: *407 event timer: 16, old: 1465480356563, new: 1465480356563
2016/06/09 15:52:31 [debug] 10825#0: posted event 0000000000000000
2016/06/09 15:52:31 [debug] 10825#0: worker cycle
2016/06/09 15:52:31 [debug] 10825#0: accept mutex locked
2016/06/09 15:52:31 [debug] 10825#0: epoll timer: 5000
2016/06/09 15:52:31 [debug] 10825#0: epoll: fd:16 ev:0011 d:00007F8015788791
2016/06/09 15:52:31 [debug] 10825#0: epoll_wait() error on fd:16 ev:0011
2016/06/09 15:52:31 [debug] 10825#0: *407 post event 00007F8015683420
2016/06/09 15:52:31 [debug] 10825#0: timer delta: 2
2016/06/09 15:52:31 [debug] 10825#0: posted events 00007F8015683420
2016/06/09 15:52:31 [debug] 10825#0: posted event 00007F8015683420
2016/06/09 15:52:31 [debug] 10825#0: *407 delete posted event 00007F8015683420
2016/06/09 15:52:31 [debug] 10825#0: *407 http lingering close handler
2016/06/09 15:52:31 [debug] 10825#0: *407 recv: fd:16 0 of 4096
2016/06/09 15:52:31 [debug] 10825#0: *407 lingering read: 0
2016/06/09 15:52:31 [debug] 10825#0: *407 http request count:1 blk:0
2016/06/09 15:52:31 [debug] 10825#0: *407 http close request
2016/06/09 15:52:31 [debug] 10825#0: *407 http log handler
2016/06/09 15:52:31 [debug] 10825#0: *407 free: 000000000244FC90, unused: 1889
2016/06/09 15:52:31 [debug] 10825#0: *407 close http connection: 16
2016/06/09 15:52:31 [debug] 10825#0: *407 SSL_shutdown: 1
2016/06/09 15:52:31 [debug] 10825#0: *407 event timer del: 16: 1465480356563
2016/06/09 15:52:31 [debug] 10825#0: *407 reusable connection: 0
2016/06/09 15:52:31 [debug] 10825#0: *407 free: 0000000002460100
2016/06/09 15:52:31 [debug] 10825#0: *407 free: 000000000237B020
2016/06/09 15:52:31 [debug] 10825#0: *407 free: 0000000002484E10, unused: 8
2016/06/09 15:52:31 [debug] 10825#0: *407 free: 000000000243E380, unused: 72
2016/06/09 15:52:31 [debug] 10825#0: posted event 0000000000000000
2016/06/09 15:52:31 [debug] 10825#0: worker cycle
2016/06/09 15:52:31 [debug] 10825#0: accept mutex locked
2016/06/09 15:52:31 [debug] 10825#0: epoll timer: -1
2016/06/09 15:52:31 [debug] 10823#0: epoll: fd:22 ev:0005 d:00007F8015788910
2016/06/09 15:52:31 [debug] 10823#0: *389 http upstream request: "/service/proxy?target=https%3A%2F%2Fxmpp.oopre.euskaltel.es%2Fmiddleware_lib.js&_=1465480377806"
2016/06/09 15:52:31 [debug] 10823#0: *389 http upstream process header
2016/06/09 15:52:31 [debug] 10823#0: *389 malloc: 00000000023768C0:4096
2016/06/09 15:52:31 [debug] 10823#0: *389 recv: fd:22 476 of 4096
2016/06/09 15:52:31 [debug] 10823#0: *389 http proxy status 404 "404 Not Found"
2016/06/09 15:52:31 [debug] 10823#0: *389 http proxy header: "Date: Thu, 09 Jun 2016 13:52:05 GMT"
2016/06/09 15:52:31 [debug] 10823#0: *389 http proxy header: "Content-Type: text/html; charset=ISO-8859-1"
2016/06/09 15:52:31 [debug] 10823#0: *389 http proxy header: "Cache-Control: must-revalidate,no-cache,no-store"
2016/06/09 15:52:31 [debug] 10823#0: *389 http proxy header: "Content-Length: 297"
2016/06/09 15:52:31 [debug] 10823#0: *389 http proxy header done
2016/06/09 15:52:31 [debug] 10823#0: *389 HTTP/1.1 404 Not Found^M