Gustaf, Despite the immense frustration for having wasted hours debugging a script, which is properly written, I’m glad you got successful results. At least now we know the problem can be in the environment.
I’ve changed servers to evaluate and mitigate environment problems. https://iurix.com/paypal-get-token <https://iurix.com/paypal-get-token> I literally copied and pasted the TCL script . *** I’m going to renew those token later, after we solve this situation. ns_log Notice "HRLLO WORLD!" set h [ns_set create] ns_set update $h Authorization "Basic QWJCN2VaRzJVeUJsb1JlVG8tUWRvRnhmMzZnZlNKbmQ1REpEbEllQ2FjZHgzdDJwMEs1aTZXUVNwTHRNVDdYT2JtUVBQREowLTZQblJLUTI6RUpmRG8zeEw2cFBhWXpKOGdRMERjeUV2Y2RSTU0tX2pGMElIZVdJc185SUJkbXF0UkN3QWRYRXloRTBkM1lNT0JIb2t\ 2STkzWXd0Q2tpSkY=" ns_set update $h "Accept" "application/json" ns_set update $h "Accept-Language" "en_US" ns_set update $h "Content-Type" "application/json" ns_http run -method POST -headers $h -body grant_type=client_credentials https://api.sandbox.paypal.com/v1/oauth2/token Regarding debugging, there’s a parameter within NS config file, from OACS installation scripts. I’ve switched set debug true within config-acs.tcl. The chunks which caught my attentions were Potential causes: 1. SSL certificate is from certbot Would that be the problem? 2. Naviserver installation NaviServer/4.99.17 NS initialization seems fine. See OACS bootstrap logs bellow Should I upgrade it? 3. OpenACS bootstraling process (i). Running https://iurix.com/paypal-get-token <https://iurix.com/paypal-get-token>, with debug parameter assigned as false, it returns [17/Nov/2019:13:00:36][20678.7f7eaaa08700][-conn:iurix:0:0-] Notice: HRLLO WORLD! [17/Nov/2019:13:00:36][20678.7f7eaaa08700][-conn:iurix:0:0-] Notice: HttpTaskRecv: connection probably closed by server (url https://api.sandbox.paypal.com/v1/oauth2/token) With debug parameter assigned as true, it returns an endless loop related to ssl socket [17/Nov/2019:12:54:31][20462.7fedd2125700][-conn:iurix:0:30-] Debug: SockConnect to api.sandbox.paypal.com: try address <173.0.82.78> [17/Nov/2019:12:54:31][20462.7fedd2125700][-conn:iurix:0:30-] Debug: Ns_SockBind called with: SockAddr family AF_INET, ip 0.0.0.0, port 0 [17/Nov/2019:12:54:31][20462.7fedd2125700][-conn:iurix:0:30-] Debug: trying to bind on: SockAddr family AF_INET, ip 0.0.0.0, port 0 [17/Nov/2019:12:54:31][20462.7fedd2125700][-conn:iurix:0:30-] Debug: ssl connect on sock 30 [17/Nov/2019:12:54:31][20462.7fedd2125700][-conn:iurix:0:30-] Debug: ssl connect on sock 30 [1 (ii.a). Debug: ssl connect on sock 30 [17/Nov/2019:12:45:04][20462.7fedd1924700][-conn:iurix:1:2-] Notice: HRLLO WORLD! [17/Nov/2019:12:45:05][20462.7feda37fe700][-sched:11-] Debug: ns:interptrace[iurix]: allocate ns:tcltrace ns_init [17/Nov/2019:12:45:05][20462.7feda37fe700][-sched:11-] Debug: Running scheduled proc search::indexer... [17/Nov/2019:12:45:05][20462.7feda37fe700][-sched:11-] Notice: dbdrv: opening database 'postgres:localhost::dbname=iurix' [17/Nov/2019:12:45:05][20462.7feda37fe700][-sched:11-] Notice: nsdbpg: Opening dbname=iurix on localhost, port [17/Nov/2019:12:45:05][20462.7feda37fe700][-sched:11-] Notice: nsdbpg(postgres): Opened connection to localhost::dbname=iurix. [17/Nov/2019:12:45:05][20462.7feda37fe700][-sched:11-] Debug: 0x7fed9402eb40 convert type none to sql < select acs_sc_binding__exists_p(:contract,:impl) > [17/Nov/2019:12:45:05][20462.7fedd1924700][-conn:iurix:1:2-] Debug: SockConnect to api.sandbox.paypal.com: try address <173.0.82.78> [17/Nov/2019:12:45:05][20462.7fedd1924700][-conn:iurix:1:2-] Debug: Ns_SockBind called with: SockAddr family AF_INET, ip 0.0.0.0, port 0 [17/Nov/2019:12:45:05][20462.7fedd1924700][-conn:iurix:1:2-] Debug: trying to bind on: SockAddr family AF_INET, ip 0.0.0.0, port 0 [17/Nov/2019:12:45:05][20462.7feda37fe700][-sched:11-] Debug: 0x7fed9402e510 convert type none to sql < select object_id, event_date, event from search_observer_queue order by event_date asc > [17/Nov/2019:12:45:05][20462.7feda37fe700][-sched:11-] Debug: Done running scheduled proc search::indexer. [17/Nov/2019:12:45:05][20462.7feda37fe700][-sched:11-] Debug: ns:interptrace[iurix]: deallocate nsproxy:cleanup a:(nil) [17/Nov/2019:12:45:05][20462.7feda37fe700][-sched:11-] Debug: ns:interptrace[iurix]: deallocate nsdb:releasehandles a:(nil) [17/Nov/2019:12:45:05][20462.7feda37fe700][-sched:11-] Debug: ns:interptrace[iurix]: deallocate ns:tcltrace ns_cleanup [17/Nov/2019:12:45:05][20462.7fedd1924700][-conn:iurix:1:2-] Debug: ssl connect on sock 30 [17/Nov/2019:12:45:05][20462.7fedd1924700][-conn:iurix:1:2-] Debug: ssl connect on sock 30 [17/Nov/2019:12:45:05][20462.7fedd1924700][-conn:iurix:1:2-] Debug: ssl connect on sock 30 [17/Nov/2019:12:45:05][20462.7fedd1924700][-conn:iurix:1:2-] Debug: ssl connect on sock 30 [17/Nov/2019:12:45:05][20462.7fedd1924700][-conn:iurix:1:2-] Debug: ssl connect on sock 30 [17/Nov/2019:12:45:05][20462.7fedd1924700][-conn:iurix:1:2-] Debug: ssl connect on sock 30 [17/Nov/2019:12:45:05][20462.7fedd1924700][-conn:iurix:1:2-] Debug: ssl connect on sock 30 [17/Nov/2019:12:45:05][20462.7fedd1924700][-conn:iurix:1:2-] Debug: ssl connect on sock 30 [17/Nov/2019:12:45:05][20462.7fedd1924700][-conn:iurix:1:2-] Debug: ssl connect on sock 30 [17/Nov/2019:12:45:05][20462.7fedd1924700][-conn:iurix:1:2-] Debug: ssl connect on sock 30 [17/Nov/2019:12:45:05][20462.7fedd1924700][-conn:iurix:1:2-] Debug: ssl connect on sock 30 [17/Nov/2019:12:45:05][20462.7fedd1924700][-conn:iurix:1:2-] Debug: ssl connect on sock 30 [17/Nov/2019:12:45:05][20462.7fedd1924700][-conn:iurix:1:2-] Debug: ssl connect on sock 30 [17/Nov/2019:12:45:05][20462.7fedd1924700][-conn:iurix:1:2-] Debug: ssl connect on sock 30 [17/Nov/2019:12:45:05][20462.7fedd1924700][-conn:iurix:1:2-] Debug: ssl connect on sock 30 [17/Nov/2019:12:45:05][20462.7fedd1924700][-conn:iurix:1:2-] Debug: ssl connect on sock 30 [17/Nov/2019:12:45:05][20462.7fedd1924700][-conn:iurix:1:2-] Debug: ssl connect on sock 30 [17/Nov/2019:12:45:05][20462.7fedd1924700][-conn:iurix:1:2-] Debug: ssl connect on sock 30 [17/Nov/2019:12:45:05][20462.7fedd1924700][-conn:iurix:1:2-] Debug: ssl connect on sock 30 [17/Nov/2019:12:45:05][20462.7fedd1924700][-conn:iurix:1:2-] Debug: ssl connect on sock 30 [17/Nov/2019:12:45:05][20462.7fedd1924700][-conn:iurix:1:2-] Debug: ssl connect on sock 30 [17/Nov/2019:12:45:05][20462.7fedd1924700][-conn:iurix:1:2-] Debug: ssl connect on sock 30 [17/Nov/2019:12:45:05][20462.7fedd1924700][-conn:iurix:1:2-] Debug: ssl connect on sock 30 [17/Nov/2019:12:45:05][20462.7fedd1924 ... (ii). Plus a few more failures related to cookies (ii.b). More failures related to cookies [17/Nov/2019:12:23:08][28463.7fe986cd4700][-conn:evex:0:1-] Debug: __ad_verify_signature: Getting token_id 759, value 4BC6F6191B5CEE67AB67BF24BA73AC2C7D29C276 ; [17/Nov/2019:12:23:08][28463.7fe986cd4700][-conn:evex:0:1-] Debug: __ad_verify_signature: Expire_Time is 1573956591 (compare to 1574004188), hash is 219DD9C5066AC83896DB148F4DAF6F37B11DB8FF [17/Nov/2019:12:23:08][28463.7fe986cd4700][-conn:evex:0:1-] Debug: __ad_verify_signature: Hash matches - Hash check OK [17/Nov/2019:12:23:08][28463.7fe986cd4700][-conn:evex:0:1-] Debug: __ad_verify_signature: Expiration time (1573956591) less than or equal to current time (1574004188) - Expiration check FAILED [17/Nov/2019:12:23:08][28463.7fe986cd4700][-conn:evex:0:1-] Debug: ad_get_signed_cookie: Verification of cookie ad_session_id FAILED [17/Nov/2019:12:23:08][28463.7fe986cd4700][-conn:evex:0:1-] Debug: OACS: Not a valid session cookie, looking for login cookie 'Cookie could not be authenticated.' [17/Nov/2019:12:23:08][28463.7fe986cd4700][-conn:evex:0:1-] Debug: OACS= sec_login_handler: enter [17/Nov/2019:12:23:08][28463.7fe986cd4700][-conn:evex:0:1-] Debug: OACS= sec_setup_session: enter [17/Nov/2019:12:23:08][28463.7fe986cd4700][-conn:evex:0:1-] Debug: OACS= empty session_id [17/Nov/2019:12:23:08][28463.7fe986cd4700][-conn:evex:0:1-] Debug: OACS= newly allocated session 342530002 [17/Nov/2019:12:23:08][28463.7fe986cd4700][-conn:evex:0:1-] Debug: OACS= about to generate session id cookie [17/Nov/2019:12:23:08][28463.7fe986cd4700][-conn:evex:0:1-] Debug: Security: 1574004188 sec_generate_session_id_cookie setting session_id=342530002, user_id=0, login_level=0 [17/Nov/2019:12:23:08][28463.7fe986cd4700][-conn:evex:0:1-] Debug: Security: Getting token_id 472, value E229479F72476418E5A43FEDE204EA7AF6FCFF7C [17/Nov/2019:12:23:08][28463.7fe986cd4700][-conn:evex:0:1-] Debug: OACS= done generating session id cookie #### 3. OpenACS bootstrapping process #### ^[[0;32m[17/Nov/2019:12:42:18][7106.7f76755ec700][-sched:22-] ^[[0m^[[0;39mNotice: nsdb: closing old handle in pool 'pool1'^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;39mNotice: nsmain: NaviServer/4.99.17 (tar-4.99.17) starting^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;39mNotice: nsmain: security info: uid=1002, euid=1002, gid=1002, egid=1002^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;39mNotice: nsmain: Tcl version: 8.6.8^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;39mNotice: nsmain: max files: soft limit 4096, hard limit 4096^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[1;39mWarning: nsmain: rl_cur (4096) > FD_SETSIZE (1024), select() calls should not be used^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;39mNotice: pool default: queueLength 90 low water 9 high water 90^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;39mNotice: nsd/init.tcl[iurix]: booting virtual server: Tcl system encoding: "utf-8"^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;39mNotice: modload: loading module nslog from file /usr/local/ns/bin/nslog.so^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;39mNotice: nslog: opened '/var/www/iurix/log//access.log'^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;39mNotice: modload: loading module nsdb from file /usr/local/ns/bin/nsdb.so^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;39mNotice: modload: loading module ns/db/driver/postgres from file /usr/local/ns/bin/nsdbpg.so^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;39mNotice: nsdbpg: version 2.3 loaded, based on PostgreSQL 9.6.10 and libbpq 90611^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;39mNotice: dbinit: set LogMinDuration for pool pool1 over 0.01 to 0.010000^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;39mNotice: dbinit: set LogMinDuration for pool pool2 over 0.01 to 0.010000^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;39mNotice: modload: loading module nsproxy from file /usr/local/ns/bin/nsproxy.so^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;39mNotice: modload: loading module nssock_v4 from file /usr/local/ns/bin/nssock.so^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;39mDebug(ns:driver): DriverInit server <iurix> threadName nssock_v4:0 proto http port 80^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;39mNotice: nssock_v4:0: enable 0 spooler thread(s) ^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;39mNotice: nssock_v4:0: enable 2 writer thread(s) for downloads >= 1024 bytes, bufsize=8192 bytes, HTML streaming 0^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;39mNotice: modload: loading module nsssl_v4 from file /usr/local/ns/bin/nsssl.so^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;39mDebug(ns:driver): DriverInit server <iurix> threadName nsssl_v4:0 proto https port 443^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;39mNotice: nsssl_v4:0: enable 0 spooler thread(s) ^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;39mNotice: nsssl_v4:0: enable 2 writer thread(s) for downloads >= 1024 bytes, bufsize=16384 bytes, HTML streaming 0^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;39mNotice: OpenSSL OpenSSL 1.1.0j 20 Nov 2018 initialized^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;39mNotice: nsssl: disabling SSLv2^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;39mNotice: nsssl: version 2.1 loaded, based on OpenSSL 1.1.0j 20 Nov 2018^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;39mNotice: modload: loading module libthread from file /usr/local/ns/lib/thread2.8.2/libthread2.8.2.so^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;34mDebug: nsd/init.tcl: loading /usr/local/ns/tcl/init.tcl^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;34mDebug: nsd/init.tcl: loading /usr/local/ns/tcl/aolserver-openacs.tcl^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;39mNotice: nx::serializer version 2.2^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;39mNotice: XOTcl 2.2.0 loaded featuring: memcount 0 profile 0 memtrace 0 assertions 1 dtrace 0 development 0^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;39mNotice: Using ns_cache based on NX 2.2.0^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;34mDebug: nsd/init.tcl: loading /usr/local/ns/tcl/cache.tcl^[[0m ^[[0;32m[17/Nov/2019:12:43:03][20368.7f8659e5b700][-main-] ^[[0m^[[0;34mDebug: nsd/init.tcl: loading /usr/local/ns/tcl/charsets.tcl^[[0m > On Nov 17, 2019, at 06:58, Gustaf Neumann <neum...@wu.ac.at> wrote: > > On 17.11.19 00:00, Iuri Sampaio wrote: >> I was expecting to get the same thing with ns_http. However, when I ran >> https://api.sandbox.paypal.com/v1/oauth2/token >> <https://api.sandbox.paypal.com/v1/oauth2/token> status returns 0 and body >> returns null. It’;s available at ttps://evex.co/paypal-checkout >> <ttps://evex.co/paypal-checkout>Hi Iuri, > > not sure, what might be wrong on your side, it is working for me (see below). > I've tried this under maxOS and Linux. Maybe a problem with versions? > If you see this failing as well with the tip version of NaviServer (which i > was testing with) > you can turn on debugging on the task level with > > ns_logctl severity Debug(task) on > > or if this is not sufficient on the driver level > > ns_logctl severity Debug(ns:driver) on > all the best > > -gn > PS: You should probably alter your credentials on api.sandbox.paypal.com > > > % set h [ns_set create] > % ns_set update $h Authorization "Basic > QWJCN2VaRzJVeUJsb1JlVG8tUWRvRnhmMzZnZlNKbmQ1REpEbEllQ2FjZHgzdDJwMEs1aTZXUVNwTHRNVDdYT2JtUVBQREowLTZQblJLUTI6RUpmRG8zeEw2cFBhWXpKOGdRMERjeUV2Y2RSTU0tX2pGMElIZVdJc185SUJkbXF0UkN3QWRYRXloRTBkM1lNT0JIb2t2STkzWXd0Q2tpSkY=" > % ns_set update $h "Accept" "application/json" > % ns_set update $h "Accept-Language" "en_US" > % ns_set update $h "Content-Type" "application/json" > % ns_http run -method POST -headers $h -body grant_type=client_credentials > https://api.sandbox.paypal.com/v1/oauth2/token > <https://api.sandbox.paypal.com/v1/oauth2/token> > > status 200 time 1:503938 headers d13 body > {{"scope":"https://uri.paypal.com/services/invoicing > https://uri.paypal.com/services/disputes/read-buyer > https://uri.paypal.com/services/payments/realtimepayment > https://uri.paypal.com/services/disputes/update-seller > https://uri.paypal.com/services/payments/payment/authcapture openid > https://uri.paypal.com/services/disputes/read-seller > https://uri.paypal.com/services/payments/refund > https://api.paypal.com/v1/vault/credit-card > https://api.paypal.com/v1/payments/.* https://uri.paypal.com/payments/payouts > https://api.paypal.com/v1/vault/credit-card/.* > https://uri.paypal.com/services/subscriptions > https://uri.paypal.com/services/applications/webhooks"; > <https://uri.paypal.com/services/invoicinghttps://uri.paypal.com/services/disputes/read-buyerhttps://uri.paypal.com/services/payments/realtimepaymenthttps://uri.paypal.com/services/disputes/update-sellerhttps://uri.paypal.com/services/payments/payment/authcaptureopenidhttps://uri.paypal.com/services/disputes/read-sellerhttps://uri.paypal.com/services/payments/refundhttps://api.paypal.com/v1/vault/credit-cardhttps://api.paypal.com/v1/payments/.*https://uri.paypal.com/payments/payoutshttps://api.paypal.com/v1/vault/credit-card/.*https://uri.paypal.com/services/subscriptionshttps://uri.paypal.com/services/applications/webhooks>,"access_token":"A21AAHMkTt1pYmD_syssLe1hHdsndPOP8WU60PHmfAcCrol39OoB3rP9vIwbIBPZzHF1jlp9_Mnu1t8NN4oA096PJzLdP6Msw","token_type":"Bearer","app_id":"APP-80W284485P519543T","expires_in":32400,"nonce":"2019-11-17T09:42:14ZFs7vTotrg8oVWwjwsFg7k9pSpMvwCc3-nCaKUrtltuE"}} > https {sslversion TLSv1.2 cipher AES256-SHA256} > _______________________________________________ > 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
