404 error service/proxy

Working with Zimbra Talk? This is your Forum, drop here your questions with the Installation, Configuration, etc.
Post Reply
anousska
Posts: 11
Joined: Wed Jun 01, 2016 12:34 pm

404 error service/proxy

Post by anousska »

Have latest talk installed (Zimbra Talk v2.2.17.2) . I am not seeing zimbra tab and when I open up browser in debugger mode i see the following error.

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)
I have checked that zimbra is able to get that url without any warnings about certificate ( with wget from proxy server and mailbox server ).
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)
IN nginx.log from proxy server:

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
User avatar
sensor
Posts: 38
Joined: Tue Apr 12, 2016 7:52 am

Re: 404 error service/proxy

Post by sensor »

anousska wrote: I have checked that zimbra is able to get that url without any warnings about certificate ( with wget from proxy server and mailbox server ).
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 ).
Is the certificate also added to zimbra java truststore?
anousska wrote: IN mailbox.log I get:
2016-06-09 11:27:58,053 INFO [qtp509886383-1480:http://172.18.167.37:8080/service/proxy ... 5464530126] [] 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)
So the proxy servlet in zimbra mailboxd complains that it is not able to get valid HTTP reply from xmpp.oopre.euskaltel.es.

The nginx.log from proxy server will not be relevant, as it just reflects what the mailbox.log already showed.
What is in /var/log/nginx/ on talk server?
anousska
Posts: 11
Joined: Wed Jun 01, 2016 12:34 pm

Re: 404 error service/proxy

Post by anousska »

Hi,

thanks for your answer.
Certificate was added in proxy server. I have added it also to mailbox server, with:

keytool -import -alias YOUR_CA_NAME -keystore /opt/zimbra/java/jre/lib/security/cacerts -storepass changeit -trustcacerts -file /PATH/TO/YOUR/CACERT

I have added ( ca root, intermediate certificate and certificate itself ) , restarted zimbra services, and I still get the error.

/var/log/nginx/error.log and access.log are empty.
User avatar
jorgedlcruz
Zimbra Alumni
Zimbra Alumni
Posts: 2782
Joined: Thu May 22, 2014 4:47 pm

Re: 404 error service/proxy

Post by jorgedlcruz »

Hello anousska,
Do you think you can use the next Wiki article, which will replace your Zimbra Collaboration SSL, and create a new one, Wildcar self-signed: And then you can replace the SSL in Zimbra Talk, without need to reinstall like this: That is the quickest solution, another one can be use Let's Encrypt SSL on your Zimbra Talk, what it's free by the way

Best regards
Jorge de la Cruz https://jorgedelacruz.es
Systems Engineer at Veeam Software https://www.veeam.com/
anousska
Posts: 11
Joined: Wed Jun 01, 2016 12:34 pm

Re: 404 error service/proxy

Post by anousska »

I have replaced the certificate in zimbra collaboration and zimbra talk, using a self-signed one ( wildcard) following the instructions of the links.

now the certificate, is green in Chrome when accessing zimbra url ( https://tablon.oopre.euskaltel.es ) or ztalk url ( https://xmpp.oopre.euskaltel.es).

But I still have the 404 error. Same error.
Last edited by anousska on Mon Jun 13, 2016 12:26 pm, edited 1 time in total.
User avatar
jorgedlcruz
Zimbra Alumni
Zimbra Alumni
Posts: 2782
Joined: Thu May 22, 2014 4:47 pm

Re: 404 error service/proxy

Post by jorgedlcruz »

From your Zimbra Server, can you run the next?

Code: Select all

wget https://xmpp.oopre.euskaltel.es/middleware_lib.js
Best regards
Jorge de la Cruz https://jorgedelacruz.es
Systems Engineer at Veeam Software https://www.veeam.com/
anousska
Posts: 11
Joined: Wed Jun 01, 2016 12:34 pm

Re: 404 error service/proxy

Post by anousska »

it has connectivity from both of them ( zimbra mailbox ) and zimbra proxy server:

[root@oo1prxpre anchors]# wget https://xmpp.oopre.euskaltel.es/middleware_lib.js
--2016-06-13 14:29:48-- https://xmpp.oopre.euskaltel.es/middleware_lib.js
Resolving xmpp.oopre.euskaltel.es... 172.18.167.8
Connecting to xmpp.oopre.euskaltel.es|172.18.167.8|:443... connected.
HTTP request sent, awaiting response... 200 OK
Length: 21327 (21K) [application/javascript]
Saving to: “middleware_lib.js”

100%[==========================================================================================>] 21,327 --.-K/s in 0s

2016-06-13 14:29:48 (298 MB/s) - “middleware_lib.js” saved [21327/21327]
User avatar
jorgedlcruz
Zimbra Alumni
Zimbra Alumni
Posts: 2782
Joined: Thu May 22, 2014 4:47 pm

Re: 404 error service/proxy

Post by jorgedlcruz »

If you have installed the new SSL certificate in both servers, ZCS and Zimbra Talk, have you restarted the services on Zimbra Collaboration, and reboot the Zimbra Talk server?

Best regards
Jorge de la Cruz https://jorgedelacruz.es
Systems Engineer at Veeam Software https://www.veeam.com/
anousska
Posts: 11
Joined: Wed Jun 01, 2016 12:34 pm

Re: 404 error service/proxy

Post by anousska »

Yes, I have restarted services on Zimbra servers ( all of them ) , and reboot ztalk server.
anousska
Posts: 11
Joined: Wed Jun 01, 2016 12:34 pm

Re: 404 error service/proxy

Post by anousska »

What is really strange to me is that I can’t see any package from zimbra mailbox server/proxy server to ztalk server, doing a tcpdump and getting the 404 error in the browser. Is it trying the connection?

In mailbox.log I keep seeing this error, but no try of that connection between servers.

2016-06-21 10:12:13,329 INFO [qtp509886383-958:http://172.18.167.37:8080/service/proxy ... 6496752421] [] 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)
at org.apache.commons.httpclient.HttpMethodBase.readResponse(HttpMethodBase.java:1735)
at org.apache.commons.httpclient.HttpMethodBase.execute(HttpMethodBase.java:1098)
at org.apache.commons.httpclient.ConnectMethod.execute(ConnectMethod.java:185)
at org.apache.commons.httpclient.HttpMethodDirector.executeConnect(HttpMethodDirector.java:496)
at org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry(HttpMethodDirector.java:391)
at org.apache.commons.httpclient.HttpMethodDirector.executeMethod(HttpMethodDirector.java:171)
at org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:397)
at com.zimbra.common.httpclient.HttpClientUtil.executeMethod(HttpClientUtil.java:58)
at com.zimbra.common.httpclient.HttpClientUtil.executeMethod(HttpClientUtil.java:44)
at com.zimbra.cs.zimlet.ProxyServlet.doProxy(ProxyServlet.java:299)
at com.zimbra.cs.zimlet.ProxyServlet.doGet(ProxyServlet.java:161)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:687)
at com.zimbra.cs.servlet.ZimbraServlet.service(ZimbraServlet.java:206)


in MBS tcpdump only see connections between Mailbox server and proxy server, no package to IP of zimbra talk server:

10:55:03.225685 IP oo1mbspre.euskaltel.es.38327 > 172.18.167.38.https: Flags [P.], seq 1:154, ack 1, win 115, options [nop,nop,TS val 1967390102 ecr 1191054161], length 153
0x0000: 4500 00cd b90a 4000 4006 daaf ac12 a725 E.....@.@......%
0x0010: ac12 a726 95b7 01bb 566d 449e c0f7 cd20 ...&....VmD.....
0x0020: 8018 0073 a730 0000 0101 080a 7543 fd96 ...s.0......uC..
0x0030: 46fe 0b51 434f 4e4e 4543 5420 786d 7070 F..QCONNECT.xmpp
0x0040: 2e6f 6f70 7265 2e65 7573 6b61 6c74 656c .oopre.euskaltel
0x0050: 2e65 733a 3434 3320 4854 5450 2f31 2e31 .es:443.HTTP/1.1
0x0060: 0d0a 5573 6572 2d41 6765 6e74 3a20 4a61 ..User-Agent:.Ja
0x0070: 6b61 7274 6120 436f 6d6d 6f6e 732d 4874 karta.Commons-Ht
0x0080: 7470 436c 6965 6e74 2f33 2e31 0d0a 486f tpClient/3.1..Ho
0x0090: 7374 3a20 786d 7070 2e6f 6f70 7265 2e65 st:.xmpp.oopre.e
0x00a0: 7573 6b61 6c74 656c 2e65 730d 0a50 726f uskaltel.es..Pro
0x00b0: 7879 2d43 6f6e 6e65 6374 696f 6e3a 204b xy-Connection:.K
0x00c0: 6565 702d 416c 6976 650d 0a0d 0a eep-Alive....
10:55:03.225803 IP 172.18.167.38.https > oo1mbspre.euskaltel.es.38327: Flags [.], ack 154, win 122, options [nop,nop,TS val 1191054162 ecr 1967390102], length 0
0x0000: 4500 0034 c671 4000 4006 cde1 ac12 a726 E..4.q@.@......&
0x0010: ac12 a725 01bb 95b7 c0f7 cd20 566d 4537 ...%........VmE7
0x0020: 8010 007a 4978 0000 0101 080a 46fe 0b52 ...zIx......F..R
0x0030: 7543 fd96 uC..
10:55:03.226021 IP 172.18.167.38.https > oo1mbspre.euskaltel.es.38327: Flags [P.], seq 1:167, ack 154, win 122, options [nop,nop,TS val 1191054162 ecr 1967390102], length 166
0x0000: 4500 00da c672 4000 4006 cd3a ac12 a726 E....r@.@..:...&
0x0010: ac12 a725 01bb 95b7 c0f7 cd20 566d 4537 ...%........VmE7
0x0020: 8018 007a b683 0000 0101 080a 46fe 0b52 ...z........F..R
0x0030: 7543 fd96 3c68 746d 6c3e 0d0a 3c68 6561 uC..<html>..<hea
0x0040: 643e 3c74 6974 6c65 3e34 3030 2042 6164 d><title>400.Bad
0x0050: 2052 6571 7565 7374 3c2f 7469 746c 653e .Request</title>
0x0060: 3c2f 6865 6164 3e0d 0a3c 626f 6479 2062 </head>..<body.b
0x0070: 6763 6f6c 6f72 3d22 7768 6974 6522 3e0d gcolor="white">.
0x0080: 0a3c 6365 6e74 6572 3e3c 6831 3e34 3030 .<center><h1>400
0x0090: 2042 6164 2052 6571 7565 7374 3c2f 6831 .Bad.Request</h1
0x00a0: 3e3c 2f63 656e 7465 723e 0d0a 3c68 723e ></center>..<hr>
0x00b0: 3c63 656e 7465 723e 6e67 696e 783c 2f63 <center>nginx</c
0x00c0: 656e 7465 723e 0d0a 3c2f 626f 6479 3e0d enter>..</body>.
0x00d0: 0a3c 2f68 746d 6c3e 0d0a .</html>..
Post Reply