Insufficient Debug logging in BcsSoapClient.php

YiffyToys commented 5 years ago

Bug description This is not about the actual issue that happened here during a Magento 2.3.2 update but about the insufficient logging with Log Level = DEBUG set according to http://dhl.support.netresearch.de/support/solutions/articles/12000051181-how-can-i-enable-the-logging- to help a shop operator to find the cause of the issue.

As #29 shows that error is this place do happen in production and people sometimes have to investigate issues happening in this place of code. In a log level as high as DEBUG, there should be some details logged that actually help to tell causes. (http response, TCP connection issues, PHP permissions,...)

The PHP SoapClient class does not offer much for debugging but https://www.php.net/manual/de/soapclient.soapclient.php mentions a trace=true attribute. This enables to log SoapClient::getLastResponse()+getLastResponseHeaders and maybe even SoapCliet::getLastRequest()+getLastRequestHeaders() in case of an exception (try, catch, log details and then and rethrow the original exception in the catch block) and would could go a long way.

In log level DEBUG It would be extremely handy to have the combined options and parameters given to SoapClient logged. Especially the SSL and cache related elements in the "options" parameter could be very helpful for the shop operator.

This could happen every time (if log level is debug) or just if an exception is cought. The later probably being much less spammy in the log files.

Steps to reproduce To reproduce the problem:

Set up with Magento 2.3.1
Verify DHL postage is working find
Upgrade to MAgento 2.3.2 using Composer ".magento maintenance:enable && composer --update-with-all-dependencies --prefer-stable require magento/product-community-edition 2.3.2 && composer update && magento cache:flush && magento setup:upgrade && magento setup:di:compile ; magento maintenance:disable ; magento cache:enable"
generate postage

Error message: failed to load external entity \"https://cig.dhl.de/cig-wsdls/com/dpdhl/wsdl/geschaeftskundenversand-api/2.2/geschaeftskundenversand-api-2.2.wsdl"

Same error message as #29

Expected behavior var/log/debug.log of Mangento should contain much more information.

Screenshots / logs

tail -f -n 0 shop2/var/log/ /var/log/apache2/.log VHOST_WEBSITE/logs/webserver.* ==> shop2/var/log/connector.log <==

==> shop2/var/log/cron.log <==

==> shop2/var/log/debug.log <==

==> shop2/var/log/exception.log <==

==> shop2/var/log/install.log <==

==> shop2/var/log/magento.cron.log <==

==> shop2/var/log/paywithamazon.log <==

==> shop2/var/log/setup.cron.log <==

==> shop2/var/log/system.log <==

==> shop2/var/log/update.cron.log <==

==> shop2/var/log/update.log <==

==> /var/log/apache2/access.log <==

==> /var/log/apache2/error.log <==

==> /var/log/apache2/other_vhosts_access.log <==

==> /var/log/apache2/ssl_access.log <==

==> SHORTENED/logs/webserver.access.log <==

==>SHORTENED/logs/webserver.error.log <==

==>SHORTENED/logs/webserver.access.log <== 109.192.195.151 - - [29/Jun/2019:14:54:38 +0200] "POST /shop2/admin_mpctcb/admin/order_shipment/save/order_id/4906/key/SHORTENED/?isAjax=true HTTP/1.1" 200 1012 "https://SHORTENED/shop2/admin_mpctcb/admin/order_shipment/new/order_id/4906/key/SHORTENED/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:67.0) Gecko/20100101 Firefox/67.0"

Environment

Magento version:

wmagento --version Magento CLI 2.3.2

PHP version:

PHP 7.2.16-1+0~20190307202206.17+jessie~1.gbpa7be82 (cli) (built: Mar 8 2019 19:32:16) ( NTS )

Module version:

composer show | grep dhl dhl/lib-shipping-mx 0.11.1 Communication types and other utilities for DHL Business Customer Shipping SOAP API access.

dhl/module-shipping-m2 0.10.3 DHL business customer shipping extension for Magento

dhl/sdk-api-parcel-management 0.1.1 SDK for calling DHL's parcel management service API

magento/module-dhl 100.3.2 N/A

FAQ Has the Knowledge Base been checked for a solution?

[X] Yes, but couldn't find anything
[ ] Yes, but solution did not work

PS: http://dhl.support.netresearch.de/support/solutions/articles/12000028196-what-does-the-message-an-error-occurred-while-creating-shipping-label-mean- mentions a "dhl_versenden.log" that doesn't exist (anymore?).

PPS: http://dhl.support.netresearch.de/support/solutions/articles/12000052314 is outdated. " config:set dev/debug/debug_logging 1" was replaced by "setup:config:set --enable-debug-logging=true" according to https://devdocs.magento.com/guides/v2.3/config-guide/cli/logging.html

ngolatka commented 5 years ago

@YiffyToys On a sidenote: the article about the log file name says:

"_... dhlversenden.log" or "debug.log"

This covers M1 and M2. In M2, the debug.log is the place to look at.

About the CLI commands to enable logging: you are correct, but that information is already in the article. Please read the CLI examples completely. They say:

NOTE: For Magento 2.2.8+ or 2.3.1+ do this instead: [other commands]

Sorry, can't contribute anything about the log content verbosity at the moment.

YiffyToys commented 5 years ago

I added logging like this:

     try {
                //parent::__construct(str_replace('https', 'http', $wsdl), $options);
                parent::__construct($wsdl, $options);
        } catch (\Exception $e) {
                $options_dump = var_export($options, true);
                $lasterror = var_export(error_get_last());
                $wsdlcontent = "error";
                try {$wsdlcontent = file_get_contents($wsdl);} catch(\Exception $x) {$wsdlcontent="Exception:" . $x->getMessage();};
                //$wsdlcontent = file_get_contents(str_replace('https', 'http', $wsdl));
          throw new \Exception('Can not create SoapClient for URL ' . $wsdl
                   . "\n  wsdl=" . $wsdlcontent
                   . "\n  options=" . $options_dump
                   . "\n  last error=" . $lasterror
                   . "\n last request=" . $this->__getLastRequest()
                   . "\n last req headers=" . $this->__getLastRequestHeaders()
                   . "\n last response=" . $this->__getLastResponse()
                   . "\n last resp headers=" . $this->__getLastResponseHeaders()
                   , $e->getCode(), $e);

//          throw $e;
        }

and in the end the file_get_contents() helped me to find the cause.

file_get_contents(): SSL operation failed with code 1. OpenSSL Error messages: error:141A318A:SSL routines:tls_process_ske_dhe:dh key too small

My interpretation of this Exception: The cig.dhl.de server of DHL is insecure (logjam attack is a year old) and the recent OpenSSL (distributed in debian marked as a security updates) no longer allow connecting to it. Looks like this information just never makes it into any log with the PHP soap_client() and it's not supposed to download the wsdl first and hand it to the soap_client to mitigate this shortcoming of PHP.

ngolatka commented 5 years ago

@YiffyToys Thanks for investigating!

Which OpenSSL version are you using?

Is it the official one from Debian, or from the "ondrej" repo (or something else)?

YiffyToys commented 5 years ago

Debian official libssl1.0.2s from May 2019.

I already tried downgrading to r and q but to no avail. (I may have missed some other lib*-openssl package.)

I can look up the exact version string and the exact ciper-string and allowed tls-versions tonight. (Old TLS vesions recently removed due to Magento Security Scanner raising an alarm because of it.)

ngolatka commented 5 years ago

On a sidenote (because this is not really the main question in this issue):

I think if the SSL version is really the problem, then our DHL module can't do much about that. The SSL handshake is not controlled by the Magento extension.

YiffyToys commented 5 years ago

Yes. an easier way to detect such things is all we can do here.

I already reported the issue with a clear openssl command-line testcase to DHL. Sadly the usual turnaround time is 7-14 days and usually results in something like "bitte wenden sie sich direkt an den Support ihrer Anbindung".

YiffyToys commented 5 years ago

libssl1.0.2s-1~deb9u1

 cat /etc/apache2/mods-enabled/ssl.conf
<IfModule mod_ssl.c>
...
        SSLCipherSuite HIGH:!aNULL:!MD5:!3DES
...
        SSLHonorCipherOrder on
...
        SSLProtocol all -SSLv2 -SSLv3 -TLSv1 -TLSv1.1
        #SSLInsecureRenegotiation on
</IfModule>

> php7.2 -v
PHP 7.2.16-1+0~20190307202206.17+jessie~1.gbpa7be82 (cli) (built: Mar  8 2019 19:32:16) ( NTS )
Copyright (c) 1997-2018 The PHP Group
Zend Engine v3.2.0, Copyright (c) 1998-2018 Zend Technologies
    with Zend OPcache v7.2.16-1+0~20190307202206.17+jessie~1.gbpa7be82, Copyright (c) 1999-2018, by Zend Technologies

>magento --version
Magento CLI 2.3.2

YiffyToys commented 5 years ago

Just for completeness and for other users with the same basic issue: Entwicklerportal@dhl.com answered that the issue is already known and worked on.

vielen Dank für den Hinweis das Thema ist bekannt und bereits in Bearbeitung.

Mit besten Grüßen René Muschard DHL Entwicklerportal-Team https://entwickler.dhl.de https://developer.dhl.com

ngolatka commented 5 years ago

@YiffyToys Did DHL get back to you about the status of the problem?

YiffyToys commented 5 years ago

@ngolatka they have not. We have a workaround in place where we try again, disallowing all DH ciphers when the specific error message happens.

ngolatka commented 5 years ago

@YiffyToys I know it is not really in the scope of this issue, but could you share your workaround here? Others might benefit from it.

YiffyToys commented 5 years ago

Update: Aparently Debian has recently changed the default OpenSSL security level to

[system_default_sect]
MinProtocol = TLSv1.2
CipherString = DEFAULT@SECLEVEL=2

thus requiring 2048 Bit for the DH parameters. This is hidden at the end of /etc/ssl/openssl.cnf . It may have come with some package updates and is not changed back when reverting to an earlier OpenSSL version because it is a system-wide configuration.

Current meaning of security levels: https://www.openssl.org/docs/man1.1.0/man3/SSL_CTX_set_security_callback.html

The DHL server has a 2048 Bit RSA key configured but only a 1024bit DH-Params file. Testcase: openssl s_client -connect cig.dhl.de:443 -cipher "EDH@SECLEVEL=1" | grep "Server Temp Key"

My current workaround is:

$bcsOptions = [
            'location' => $config->getApiEndpoint(),
            'login'    => $config->getAuthUsername(),
            'password' => $config->getAuthPassword(),
            'classmap' => self::$classmap,
            'trace'    => true,
            'features' => SOAP_SINGLE_ELEMENT_ARRAYS,
    'stream_context' => stream_context_create(array(
          'ssl' => array(
                'ciphers' => 'DEFAULT:!DH',
          )
    ))
        ];

I have informed Entwicklerportal@dhl.com about this updates information.

YiffyToys commented 2 years ago

Same thing again. This time I had to do the same logging modification to find out it could not read a missing SSL CA certificate. (after changing to a new server) Because it still wasn't logging the actual SOAP errors with debug logging in Magento and DHL-logging at the highest level the UI allows. Debug and DHL log contained nothing at all and the UI just had a generic error message hardcoded in vendor/dhl/module-carrier-paket/Model/Pipeline/CreateShipments/Stage/SendRequestStage.php where the actual exception and thus cause of the failure was swallowed and neither reported to the UI nor logged.

ngolatka commented 1 year ago

Closing this issue because dhl-module-shipping-m2 is not maintained anymore.

Please refer to https://github.com/netresearch/dhl-shipping-m2 which is currently actively developed and supported.

netresearch / dhl-module-shipping-m2

Insufficient Debug logging in BcsSoapClient.php #59