The end of SSL request seems fine, except for 2 evidences that caught my attention
i. the long loop of ssl connect on sock 28; > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug: ssl > connect on sock 28 ii. the end of logging has an error [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): Ns_TaskCallback task 0x7f6a40458f70 [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): taskDone 0 httpPtr->finalSockState 128 error (null) [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): Ns_TaskRun 28: NS_SOCK_INIT done iii. api.sandbox.papal.com <http://api.sandbox.papal.com/> still rejects ns_http connections but allow curl and Postman. That’s very weird. [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Notice: HttpTaskRecv: connection probably closed by server (url https://api.sandbox.paypal.com/v1/oauth2/token) Do you still get successful results ? https://iurix.com/paypal-get-token <https://iurix.com/paypal-get-token> > On Nov 17, 2019, at 13:53, Iuri Sampaio <i...@iurix.com> wrote: > > As indicated in the log, I’ve edited /etc/hosts, and assigned 173.0.82.78 to > api.sandbox.paypal.com <http://api.sandbox.paypal.com/> > but nothing has changed. > > > > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug: > 0x7f6a40060f10 REUSE sql > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Notice: HRLLO > WORLD! > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > connect to [api.sandbox.paypal.com <http://api.sandbox.paypal.com/>]:443 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug: > SockConnect to api.sandbox.paypal.com <http://api.sandbox.paypal.com/>: try > address <173.0.82.78> async 1 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug: > Ns_SockBind called with: SockAddr family AF_INET, ip 0.0.0.0, port 0 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug: trying to > bind on: SockAddr family AF_INET, ip 0.0.0.0, port 0 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug: ssl > connect on sock 28 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug: ssl > connect on sock 28 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug: ssl > connect on sock 28 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug: ssl > connect on sock 28 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug: ssl > connect on sock 28 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug: ssl > connect on sock 28 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug: ssl > connect on sock 28 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug: ssl > connect on sock 28 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug: ssl > connect on sock 28 > [17/N > > > > ##### > ## logs ends with the following messages > ##### > > > > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug: ssl > connect on sock 28 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug: ssl > connect on sock 28 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug: ssl > connect on sock 28 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug: ssl > connect on sock 28 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug: ssl > connect on sock 28 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug: ssl > connect on sock 28 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug: ssl > connect on sock 28 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > HttpProc operation 80 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > Ns_TaskCallback task 0x7f6a40458f70 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > taskDone 0 httpPtr->finalSockState 128 error (null) > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > Ns_TaskRun 28: NS_SOCK_INIT done > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > Ns_TaskRun 28: run task with revents 04 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > RunTask: revents 0: 4, task flags 000c > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > HttpProc operation 02 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > NS_SOCK_WRITE sendSpoolMode 0 fd 0 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > HttpProc NS_SOCK_WRITE will send dsptr 0x7f6a403cd900 next 0x7f6a403cd900 len > 485 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > HttpTaskSend sent 485 bytes (of 485) > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > HttpProc all data sent, switch to read reply > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > Ns_TaskCallback task 0x7f6a40458f70 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > taskDone 0 httpPtr->finalSockState 2 error (null) > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > Ns_TaskRun 28: run task with revents 01 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > RunTask: revents 0: 1, task flags 000c > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > HttpProc operation 01 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > NS_SOCK_READ > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > HttpTaskRecv received 81 bytes (buffer size 16384) > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > HttpTaskRecv got 81 bytes > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > HttpTaskRecv got 81 bytes spoolFd 0 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > HttpTaskRecv appends 81 bytes to buffer > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > Ns_HttpAppendBuffer: got 81 bytes flags 000000 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > HttpTaskRecv appends 81 bytes to buffer (replyHeaderSize 0) > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > Ns_HttpCheckHeader replyHeaderSize 0 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > Ns_HttpCheckHeader we have EOH 0x7f6a403cd94d > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > Ns_HttpCheckHeader SETTING replyHeaderSize 81 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > Ns_HttpCheckSpool replyHeaderSize 81 status 0 httpPtr->replyHeaders > 0x7f6a405bec90 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > Ns_HttpCheckSpool replyHeaderSize 81 status 0 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > ProcessReplyHeaderFields 0x7f6a405bec90 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > Ns_HttpCheckSpool have content-length 0 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > taskDone 0 httpPtr->finalSockState 1 error (null) > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > Ns_TaskRun 28: run task with revents 01 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > RunTask: revents 0: 1, task flags 000c > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > HttpProc operation 01 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > NS_SOCK_READ > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Notice: > HttpTaskRecv: connection probably closed by server (url > https://api.sandbox.paypal.com/v1/oauth2/token > <https://api.sandbox.paypal.com/v1/oauth2/token>) > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > HttpTaskRecv received 0 bytes (buffer size 16384) > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > HttpTaskRecv got 0 bytes > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > taskDone 1 httpPtr->finalSockState 1 error (null) > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > Ns_TaskRun 28: NS_SOCK_DONE done > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > HttpProc operation 10 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > NS_SOCK_DONE doneCallback <(null)> > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > NS_SOCK_DONE no sock callback > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > taskDone 1 httpPtr->finalSockState 16 error (null) > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(task): > HttpClose 0x7f6a405c3a20 FREE TASK 0x7f6a40458f70 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug: > ns:interptrace[iurix]: freeconn ns:tcltrace ::xo::freeconn > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug: > ns:interptrace[iurix]: deallocate nsproxy:cleanup a:(nil) > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug: > ns:interptrace[iurix]: deallocate nsdb:releasehandles a:(nil) > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug: > ns:interptrace[iurix]: deallocate ns:tcltrace ns_cleanup > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug: > Ns_ConnClose 0x559c71ed4b10 stream 000000 chunk 000000 via writer 000000 > sockPtr 0x7f6a3c0034c0 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(ns:driver): > NsSockClose sockPtr 0x7f6a3c0034c0 (5) keep -1 > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(ns:driver): > NsSockClose calls RequestFree > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(ns:driver): > === RequestFree cleans 0x7f6a3c0036c0 (avail 0 keep 1 length 0 contentLength > 0) > [17/Nov/2019:13:49:55][634.7f6a4f62b700][-conn:iurix:0:44-] Debug(ns:driver): > RequestFree does not call Ns_ResetRequest on 0x7f6a3c0036c8 > [17/Nov/2019:13:49:55][634.7f6a4e629700][-driver:nsssl_v4:0-] > Debug(ns:driver): === PollWait returned 1, trigger[0] 1 > > > > >> On Nov 17, 2019, at 13:47, Iuri Sampaio <i...@iurix.com >> <mailto:i...@iurix.com>> wrote: >> >> NS has been updated to .18 >> I’ve set logging as recommended. >> >> #ns_logctl severity "Debug(ns:driver)" $debug >> >> >> >> ns_logctl severity Debug(ns:driver) on >> ns_logctl severity Debug(task) on >> >> Logs are still the same >> >> [17/Nov/2019:13:44:50][634.7f6a4ee2a700][-conn:iurix:1:9-] Notice: HRLLO >> WORLD! >> [17/Nov/2019:13:44:50][634.7f6a4ee2a700][-conn:iurix:1:9-] Debug(task): >> connect to [api.sandbox.paypal.com <http://api.sandbox.paypal.com/>]:443 >> [17/Nov/2019:13:44:50][634.7f6a4ee2a700][-conn:iurix:1:9-] Debug: >> SockConnect to api.sandbox.paypal.com <http://api.sandbox.paypal.com/>: try >> address <173.0.82.78> async 1 >> [17/Nov/2019:13:44:50][634.7f6a4ee2a700][-conn:iurix:1:9-] Debug: >> Ns_SockBind called with: SockAddr family AF_INET, ip 0.0.0.0, port 0 >> [17/Nov/2019:13:44:50][634.7f6a4ee2a700][-conn:iurix:1:9-] Debug: trying to >> bind on: SockAddr family AF_INET, ip 0.0.0.0, port 0 >> [17/Nov/2019:13:44:51][634.7f6a4ee2a700][-conn:iurix:1:9-] Debug: ssl >> connect on sock 28 >> [17/Nov/2019:13:44:51][634.7f6a4ee2a700][-conn:iurix:1:9-] Debug: ssl >> connect on sock 28 >> [17/Nov/2019:13:44:51][634.7f6a4ee2a700][-conn:iurix:1:9-] Debug: ssl >> connect on sock 28 >> [17/Nov/2019:13:44:51][634.7f6a4ee2a700][-conn:iurix:1:9-] Debug: ssl >> connect on sock 28 >> [17/Nov/2019:13:44:51][634.7f6a4ee2a700][-conn:iurix:1:9-] Debug: ssl >> connect on sock 28 >> [17/Nov/2019:13:44:51][634.7f6a4ee2a700][-conn:iurix:1:9-] Debug: ssl >> connect on sock 28 >> [17/Nov/2019:13:44:51][634.7f6a4ee2a700][-conn:iurix:1:9-] Debug: ssl >> connect on sock 28 >> [17/Nov/2019:13:44:51][634.7f6a4ee2a700][-conn:iurix:1:9-] Debug: ssl >> connect on sock 28 >> [17/Nov/2019:13:44:51][634.7f6a4ee2a700][-conn:iurix:1:9-] Debug: ssl >> connect on sock 28 >> [17/ >> >>> On Nov 17, 2019, at 13:16, Gustaf Neumann <neum...@wu.ac.at >>> <mailto:neum...@wu.ac.at>> wrote: >>> >>> On 17.11.19 17:04, Iuri Sampaio wrote: >>>> NaviServer/4.99.17 >>>> >>>> Should I upgrade it? >>> yes. There are fixes for partly configured IPv6 setups in the 4.99.18 >>> release >>> (read the NEWS file). >>> I would recommend to use the tip version (the same i have used). >>> ... and set logging as recommended in my last mail. >>> -g >>> _______________________________________________ >>> naviserver-devel mailing list >>> naviserver-devel@lists.sourceforge.net >>> <mailto:naviserver-devel@lists.sourceforge.net> >>> https://lists.sourceforge.net/lists/listinfo/naviserver-devel >>> <https://lists.sourceforge.net/lists/listinfo/naviserver-devel> >> >> _______________________________________________ >> naviserver-devel mailing list >> naviserver-devel@lists.sourceforge.net >> <mailto:naviserver-devel@lists.sourceforge.net> >> https://lists.sourceforge.net/lists/listinfo/naviserver-devel > > _______________________________________________ > naviserver-devel mailing list > naviserver-devel@lists.sourceforge.net > https://lists.sourceforge.net/lists/listinfo/naviserver-devel
_______________________________________________ naviserver-devel mailing list naviserver-devel@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/naviserver-devel
