2023-11-04
Als ich eine Erwerbsarbeit in der IT anfing, war das als Linux Administratorin im Bereich des E-Commerce Managed-Hosting gewesen. Deshalb habe ich bis heute einen leichten Fokus auf Shopware und Magento auf Ubuntu Kisten und was dazu gehört. Nun kommt es gelegentlich vor, dass ich für andere ehrenamtlich oder als Freelancerin Administrationsarbeit tätige oder Fehler behebe. Große Abenteuer sind hierbei immer Situationen, die mit netcup zu tun haben. Der Preis von netcup muss einen Grund haben und dieser lautet geringer Service und teils mangelnde Kompetenzen. So zum Beispiel als netcup die Domain von unseren Hackspace kaputt spielten und erst nach Stunden sich zurückmeldeten, dass die das Ticket entgegennahmen (vorher mussten wir noch dort anrufen), womit netcup ins Wochenende ging und bis zum nächsten Werktag erstmal nichts taten. Eine Kommunikation war nicht vorhanden und wir mussten bis zum Dienstag warten, bevor unsere Domain wieder verfügbar war. Ein anderer Space berichtete ähnliches, als die Admins dort ihre Domain zu netcup umgezogen haben. In diesem Blogpost möchte darüber berichten, wie sich ein geglaubtes einfaches Anwendungsproblem zu einem DNS und Netzwerk Problem bei netcup eskalierte.
Die Tage erhielt ich eine Nachricht, dass aus dem Nichts die Generierung von Rechnungen und Lieferscheinen in Shopware Admin Backend lange dauern. Es gab nur einen Hinweis, welchen ich erhielt:
2023/11/03 23:06:23 [error] 810358#810358: *130511 upstream timed out (110: Connection timed out) while reading response header from upstream, client: <IPv4>, server: shop.domain.tld, request: "GET /api/_action/document/<string>/<string>?download=1 HTTP/1.1", upstream: "fastcgi://unix:/run/php/php-fpm.sock", host: "shop.domain.tld", referrer: "https://shop.domain.tld/admin"
Diese Meldung entsammt Nginx und weist daraufhin, dass ein Request in ein Timeout lief. Da Shopware eine Anwerndung ist, welche in PHP geschrieben wurde, liegt der Fehler nicht bei Nginx sondern muss sich irgendwo im PHP befinden. Meine Vermutungen waren:
Zwischenzeitlich wurde mir gestanden, dass drei Updates für Plugins eingespielt wurden. Also mache ich mir eine Testbestellung und generiere mir Dokument. Die Debuglogs von php-fpm ergaben nichts relevantes. Es wurde der DomPDF angefasst und ausgeführt.
[03-Nov-2023 23:45:13.257570] [pool www] pid 788248
script_filename = <PATH/TO/SHOPWARE/>/public/index.php
[0x00007f076f214430] file_get_contents() <PATH/TO/SHOPWARE/>/vendor/shopwarelabs/dompdf/src/Helpers.php:870
[0x00007f076f2142a0] getFileContent() <PATH/TO/SHOPWARE/>/vendor/shopwarelabs/dompdf/src/Css/Stylesheet.php:399
[0x00007f076f214120] load_css_file() <PATH/TO/SHOPWARE/>/vendor/shopwarelabs/dompdf/src/Dompdf.php:649
[0x00007f076f213fc0] processHtml() <PATH/TO/SHOPWARE/>/vendor/shopwarelabs/dompdf/src/Dompdf.php:761
[0x00007f076f213e00] render() <PATH/TO/SHOPWARE/>/vendor/shopware/core/Checkout/Document/FileGenerator/PdfGenerator.php:89
[0x00007f076f213d50] generate() <PATH/TO/SHOPWARE/>/vendor/shopware/core/Checkout/Document/DocumentService.php:577
[0x00007f076f213c50] generateDocument() <PATH/TO/SHOPWARE/>/vendor/shopware/core/Checkout/Document/DocumentService.php:215
[0x00007f076f213b50] getDocument() <PATH/TO/SHOPWARE/>/vendor/shopware/core/Checkout/Document/Controller/DocumentController.php:107
[0x00007f076f213a10] downloadDocument() <PATH/TO/SHOPWARE/>/vendor/symfony/http-kernel/HttpKernel.php:163
[0x00007f076f213930] handleRaw() <PATH/TO/SHOPWARE/>/vendor/symfony/http-kernel/HttpKernel.php:75
[0x00007f076f213860] handle() <PATH/TO/SHOPWARE/>/vendor/symfony/http-kernel/Kernel.php:202
[0x00007f076f2137a0] handle() <PATH/TO/SHOPWARE/>/vendor/symfony/http-kernel/HttpCache/SubRequestHandler.php:86
[0x00007f076f213630] handle() <PATH/TO/SHOPWARE/>/vendor/symfony/http-kernel/HttpCache/HttpCache.php:479
[0x00007f076f213560] forward() <PATH/TO/SHOPWARE/>/vendor/symfony/http-kernel/HttpCache/HttpCache.php:452
[0x00007f076f2134b0] fetch() <PATH/TO/SHOPWARE/>/vendor/symfony/http-kernel/HttpCache/HttpCache.php:346
[0x00007f076f213400] lookup() <PATH/TO/SHOPWARE/>/vendor/symfony/http-kernel/HttpCache/HttpCache.php:224
[0x00007f076f213350] handle() <PATH/TO/SHOPWARE/>/vendor/shopware/core/HttpKernel.php:156
[0x00007f076f213230] doHandle() <PATH/TO/SHOPWARE/>/vendor/shopware/core/HttpKernel.php:81
[0x00007f076f213150] handle() <PATH/TO/SHOPWARE/>/public/index.php:85
Also auch das was ich haben möchte. Die PHP Log gibt mir auch keine relevanten Informationen.
[03-Nov-2023 23:45:50.940171] DEBUG: pid 788227, fpm_pctl_perform_idle_server_maintenance(), line 382: [pool www] currently 2 active children, 18 spare children, 20 running children. Spawning rate 1
[03-Nov-2023 23:45:51.940599] DEBUG: pid 788227, fpm_pctl_perform_idle_server_maintenance(), line 382: [pool www] currently 1 active children, 19 spare children, 20 running children. Spawning rate 1
[03-Nov-2023 23:45:52.941009] DEBUG: pid 788227, fpm_pctl_perform_idle_server_maintenance(), line 382: [pool www] currently 1 active children, 19 spare children, 20 running children. Spawning rate 1
[03-Nov-2023 23:45:53.941418] DEBUG: pid 788227, fpm_pctl_perform_idle_server_maintenance(), line 382: [pool www] currently 1 active children, 19 spare children, 20 running children. Spawning rate 1
[03-Nov-2023 23:45:54.941971] DEBUG: pid 788227, fpm_pctl_perform_idle_server_maintenance(), line 382: [pool www] currently 1 active children, 19 spare children, 20 running children. Spawning rate 1
[03-Nov-2023 23:45:55.942247] DEBUG: pid 788227, fpm_pctl_perform_idle_server_maintenance(), line 382: [pool www] currently 1 active children, 19 spare children, 20 running children. Spawning rate 1
[03-Nov-2023 23:45:56.942708] DEBUG: pid 788227, fpm_pctl_perform_idle_server_maintenance(), line 382: [pool www] currently 1 active children, 19 spare children, 20 running children. Spawning rate 1
[03-Nov-2023 23:45:57.943132] DEBUG: pid 788227, fpm_pctl_perform_idle_server_maintenance(), line 382: [pool www] currently 1 active children, 19 spare children, 20 running children. Spawning rate 1
[03-Nov-2023 23:45:58.943527] DEBUG: pid 788227, fpm_pctl_perform_idle_server_maintenance(), line 382: [pool www] currently 1 active children, 19 spare children, 20 running children. Spawning rate 1
[03-Nov-2023 23:45:59.943928] DEBUG: pid 788227, fpm_pctl_perform_idle_server_maintenance(), line 382: [pool www] currently 2 active children, 18 spare children, 20 running children. Spawning rate 1
Sieht eher danach aus, dass sich PHP langweilt. Da ist Luft nach mehr vorhanden. Wie sieht es auf der Seie von MySQL aus? Langlaufende Queries? Vollalaufende Connections? Schließlich muss PHP zum Rendern der Postionen in der Datenbank schauen, was da drine stehen soll.
mysql -e 'SHOW FULL PROCESSLIST\G;'
*************************** 1. row ***************************
Id: 1
User: system user
Host:
db: NULL
Command: Daemon
Time: NULL
State: InnoDB purge worker
Info: NULL
Progress: 0.000
*************************** 2. row ***************************
Id: 2
User: system user
Host:
db: NULL
Command: Daemon
Time: NULL
State: InnoDB purge worker
Info: NULL
Progress: 0.000
*************************** 3. row ***************************
Id: 3
User: system user
Host:
db: NULL
Command: Daemon
Time: NULL
State: InnoDB purge coordinator
Info: NULL
Progress: 0.000
*************************** 4. row ***************************
Id: 4
User: system user
Host:
db: NULL
Command: Daemon
Time: NULL
State: InnoDB purge worker
Info: NULL
Progress: 0.000
*************************** 5. row ***************************
Id: 5
User: system user
Host:
db: NULL
Command: Daemon
Time: NULL
State: InnoDB shutdown handler
Info: NULL
Progress: 0.000
*************************** 6. row ***************************
Id: 665923
User: root
Host: localhost
db: NULL
Command: Query
Time: 0
State: Init
Info: SHOW FULL PROCESSLIST
Progress: 0.000
Nein, auch MySQL langweilt sich. Somit bleibt noch ein blick in die Shopware Log Files.
[...]
[2023-11-03T23:45:59.267505+00:00] request.ERROR: Uncaught PHP Exception Symfony\Component\HttpKernel\Exception\NotFoundHttpException: "No route found for "GET https://shop.domain.tld/api/_action/plugin-name/health/status" (from "https://shop.domain.tld/admin")" at <PATH/TO/SHOPWARE/>/vendor/symfony/http-kernel/EventListener/RouterListener.php line 135 {"exception":"[object] (Symfony\\Component\\HttpKernel\\Exception\\NotFoundHttpException(code: 0): No route found for \"GET https://shop.domain.tld/api/_action/plugin-name/health/status\" (from \"https://shop.domain.tld/admin\") at <PATH/TO/SHOPWARE/>/vendor/symfony/http-kernel/EventListener/RouterListener.php:135)\n[previous exception] [object] (Symfony\\Component\\Routing\\Exception\\ResourceNotFoundException(code: 0): No routes found for \"/api/_action/plugin-name/health/status/\". at <PATH/TO/SHOPWARE/>/vendor/symfony/routing/Matcher/Dumper/CompiledUrlMatcherTrait.php:74)"} []
[...]
Da gibt es andere Probleme, aber keinen direkten Hinweis darauf, dass etwas nicht stimmt. Ergo stand ich da, ohne zu wissen was die Ursache ist. Hier blieb mir aktuell einmal die Plugins nach und nach An und Aus zu schalten, dabei gegen den Shop treten und gucken ob etwas wackelt. Alles ohne Erfolg. Ab diesen Punk kann ich ausschließen dass:
Ab hier hilft mir aktuell nur noch strace
weiter. Wer es nicht kennt, strace
ist ein Diagnose-, Debugging- und Anleitungs-Userspace-Dienstprogramm für Linux. Es wird verwendet, um Interaktionen zwischen Prozessen und dem Linux-Kernel zu überwachen und zu manipulieren, zu denen Systemaufrufe, Signalübermittlungen und Änderungen des Prozessstatus gehören.
Da ich mir bewusst bin, dass der Fehler bei der Generierung des PDF liegen muss, muss ich strace an php-fpm ansetzen.
strace -f $(pgrep php-fpm | sed 's/\([0-9]*\)/\-p \1/g') -o /tmp/strace.txt
mit dem Befehl schreibe ich mir eine txt Datei, mit allen php-fpm Child Prozessen, damit ich mir diese in ruhe durch lesen kann und wer strace kennt, da steht jedemenge Zeug drine. Wer es noch nicht kennt, hier ein Auszug:
[...]
788258 restart_syscall(<... resuming interrupted read ...> <unfinished ...>
788258 <... restart_syscall resumed>) = 0
788258 getrandom("\x94\x16\x89\xbf\x80\xf1\x5d\xc6\x0a\x2e\xb0\x3c\xfa\x4d\x8d\xf1", 16, 0) = 16
788258 sendto(5, "\272\0\0\0\3SELECT id FROM enqueue WHER"..., 190, MSG_DONTWAIT, NULL, 0) = 190
788258 poll([{fd=5, events=POLLIN|POLLERR|POLLHUP}], 1, 86400000) = 1 ([{fd=5, revents=POLLIN}])
788258 recvfrom(5, "\1\0\0\1\0012\0\0\2\3def\nshopwaredb\7enqueue"..., 32768, MSG_DONTWAIT, NULL, NULL) = 77
788258 stat("<PATH/TO/SHOPWARE/>/var/cache/prod_h49bb3924ef6e5d0f1fcf2d88c93edb2d/pools/app/8Yd34KvmHO/E/A/30cvnUWHXZIa5VxTuJ5w", 0x7fff6882d050) = -1 ENOENT (No such file or directory)
788258 sendto(5, "\211\0\0\0\3DELETE FROM enqueue WHERE ("..., 141, MSG_DONTWAIT, NULL, 0) = 141
788258 poll([{fd=5, events=POLLIN|POLLERR|POLLHUP}], 1, 86400000) = 1 ([{fd=5, revents=POLLIN}])
788258 recvfrom(5, "\7\0\0\1\0\0\0\2\0\0\0", 32768, MSG_DONTWAIT, NULL, NULL) = 11
788258 sendto(5, "|\0\0\0\3UPDATE enqueue SET delivery"..., 128, MSG_DONTWAIT, NULL, 0) = 128
788258 poll([{fd=5, events=POLLIN|POLLERR|POLLHUP}], 1, 86400000) = 1 ([{fd=5, revents=POLLIN}])
788258 recvfrom(5, "0\0\0\1\0\0\0\2\0\0\0(Rows matched: 0 Cha"..., 32768, MSG_DONTWAIT, NULL, NULL) = 52
788258 getrandom("\x24\x9e\x60\x83\x00\x3f\x70\x69\x57\x20\xfc\x2f\xef\xc7\x76\xe4", 16, 0) = 16
788258 sendto(5, "\272\0\0\0\3SELECT id FROM enqueue WHER"..., 190, MSG_DONTWAIT, NULL, 0) = 190
788258 poll([{fd=5, events=POLLIN|POLLERR|POLLHUP}], 1, 86400000) = 1 ([{fd=5, revents=POLLIN}])
788258 recvfrom(5, "\1\0\0\1\0012\0\0\2\3def\nshopwaredb\7enqueue"..., 32768, MSG_DONTWAIT, NULL, NULL) = 77
788258 clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=98409000}, NULL) = 0
788258 getrandom("\x8d\x47\x6c\x4b\x41\x0b\x0d\x44\xed\x9f\xe8\x06\x83\x75\xa2\x5b", 16, 0) = 16
788258 sendto(5, "\272\0\0\0\3SELECT id FROM enqueue WHER"..., 190, MSG_DONTWAIT, NULL, 0) = 190
[...]
Ich habe für dieses Beispiel einen zufälligen Teil des Prozesses mit der ID 788258 heraus kopiert. Persönlich kenne ich mich mit strace nicht detailiert aus, aber auf dem ersten Blick erkenn ich bei den sendto's
irgendwelche SQL Queries. Sprich PHP muss hier irgendwas in der Datenbank machen wollen.
Wenn ich jetzt mit less mir die Ausgabe anzeigen lasse und damit nach PDF suche, finde ich jede Menge ergebnise. 537 mal kommt das Wort PDF im Strace vor. Somit kann ich mich aktuell nur durch die Ausgabe bewegen und lesen was geschieht. Tatsächlich sehe ich, dass PHP das jeweilige Skript zur Generierung der PDFs anpackt und dinge tut. Aus der Ausgabe kann ich aber keine timings erkennen oder herauslesen, wo es zum Problem kommen soll.
Meine persönliche Erfahrung gab mir ein Hinweis darauf, dass eventuell ein Request an einen externen Host stattfindet und dieser in ein Time Out rennt. Aber um das zu replizieren, schreibe ich mir kein file, sondern lasse strace
laufen während ich mir einen Lieferschein erstelle und schaue dabei nach, an welcher stelle bleibt dieser hängen. Da ich nicht weiß im welchen Child Prozess das PDF generiert werden soll und strace
die Ausgaben mischen wird, mache ich noch ein grep nach PDF und schaue was passiert.
strace -f $(pgrep php-fpm | sed 's/\([0-9]*\)/\-p \1/g') 2>&1 | grep -i pdf
Tatsächlich bleibt die Ausgabe an der folgenden Stelle stehen, bevor es nach ca. einer Minute weiter geht:
788250 stat("<PATH/TO/SHOPWARE/>/vendor/shopwarelabs/dompdf/src/Css/Color.php", {st_mode=S_IFREG|0644, st_size=10259, ...}) = 0
Damit habe ich etwas wonach in meiner niedergeschriebenen strace Ausgabe suchen kann und siehe da, ich finde etwas interessantes:
[...]
788250 socket(AF_INET6, SOCK_DGRAM, IPPROTO_IP) = 7
788250 close(7) = 0
788250 stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=717, ...}) = 0
788250 openat(AT_FDCWD, "/etc/hosts", O_RDONLY|O_CLOEXEC) = 7
788250 lseek(7, 0, SEEK_CUR) = 0
788250 fstat(7, {st_mode=S_IFREG|0644, st_size=341, ...}) = 0
788250 read(7, "127.0.0.1\tlocalhost shop.domain."..., 4096) = 341
788250 lseek(7, 0, SEEK_CUR) = 341
788250 read(7, "", 4096) = 0
788250 close(7) = 0
788250 socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 7
788250 setsockopt(7, SOL_IP, IP_RECVERR, [1], 4) = 0
788250 connect(7, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.53")}, 16) = 0
788250 poll([{fd=7, events=POLLOUT}], 1, 0) = 1 ([{fd=7, revents=POLLOUT}])
788250 sendmmsg(7, [{msg_hdr={msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\267\207\1 \0\1\0\0\0\0\0\1\5fonts\ngoogleapis\3co"..., iov_len=49}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, msg_len=49}, {msg_hdr={msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\22\204\1 \0\1\0\0\0\0\0\1\5fonts\ngoogleapis\3co"..., iov_len=49}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, msg_len=49}], 2, MSG_NOSIGNAL) = 2
788250 poll([{fd=7, events=POLLIN}], 1, 5000) = 1 ([{fd=7, revents=POLLIN}])
788250 ioctl(7, FIONREAD, [65]) = 0
788250 recvfrom(7, "\267\207\201\200\0\1\0\1\0\0\0\1\5fonts\ngoogleapis\3co"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.53")}, [28->16]) = 65
788250 poll([{fd=7, events=POLLIN}], 1, 4998) = 1 ([{fd=7, revents=POLLIN}])
788250 ioctl(7, FIONREAD, [77]) = 0
788250 recvfrom(7, "\22\204\201\200\0\1\0\1\0\0\0\1\5fonts\ngoogleapis\3co"..., 65536, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.53")}, [28->16]) = 77
788250 close(7) = 0
788250 socket(AF_NETLINK, SOCK_RAW|SOCK_CLOEXEC, NETLINK_ROUTE) = 7
788250 bind(7, {sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, 12) = 0
788250 getsockname(7, {sa_family=AF_NETLINK, nl_pid=788250, nl_groups=00000000}, [12]) = 0
788250 sendto(7, {{len=20, type=RTM_GETADDR, flags=NLM_F_REQUEST|NLM_F_DUMP, seq=1699052468, pid=0}, {ifa_family=AF_UNSPEC, ...}}, 20, 0, {sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, 12) = 20
788250 recvmsg(7, {msg_name={sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, msg_namelen=12, msg_iov=[{iov_base=[{{len=76, type=RTM_NEWADDR, flags=NLM_F_MULTI, seq=1699052468, pid=788250}, {ifa_family=AF_INET, ifa_prefixlen=8, ifa_flags=IFA_F_PERMANENT, ifa_scope=RT_SCOPE_HOST, ifa_index=if_nametoindex("lo")}, [{{nla_len=8, nla_type=IFA_ADDRESS}, inet_addr("127.0.0.1")}, {{nla_len=8, nla_type=IFA_LOCAL}, inet_addr("127.0.0.1")}, {{nla_len=7, nla_type=IFA_LABEL}, "lo"}, {{nla_len=8, nla_type=IFA_FLAGS}, IFA_F_PERMANENT}, {{nla_len=20, nla_type=IFA_CACHEINFO}, {ifa_prefered=4294967295, ifa_valid=4294967295, cstamp=300, tstamp=300}}]}, {{len=88, type=RTM_NEWADDR, flags=NLM_F_MULTI, seq=1699052468, pid=788250}, {ifa_family=AF_INET, ifa_prefixlen=22, ifa_flags=IFA_F_PERMANENT, ifa_scope=RT_SCOPE_UNIVERSE, ifa_index=if_nametoindex("eth0")}, [{{nla_len=8, nla_type=IFA_ADDRESS}, inet_addr("193.26.159.211")}, {{nla_len=8, nla_type=IFA_LOCAL}, inet_addr("193.26.159.211")}, {{nla_len=8, nla_type=IFA_BROADCAST}, inet_addr("193.26.159.255")}, {{nla_len=9, nla_type=IFA_LABEL}, "eth0"}, {{nla_len=8, nla_type=IFA_FLAGS}, IFA_F_PERMANENT}, {{nla_len=20, nla_type=IFA_CACHEINFO}, {ifa_prefered=4294967295, ifa_valid=4294967295, cstamp=395, tstamp=395}}]}], iov_len=4096}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 164
788250 recvmsg(7, {msg_name={sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, msg_namelen=12, msg_iov=[{iov_base=[{{len=72, type=RTM_NEWADDR, flags=NLM_F_MULTI, seq=1699052468, pid=788250}, {ifa_family=AF_INET6, ifa_prefixlen=128, ifa_flags=IFA_F_PERMANENT, ifa_scope=RT_SCOPE_HOST, ifa_index=if_nametoindex("lo")}, [{{nla_len=20, nla_type=IFA_ADDRESS}, inet_pton(AF_INET6, "::1")}, {{nla_len=20, nla_type=IFA_CACHEINFO}, {ifa_prefered=4294967295, ifa_valid=4294967295, cstamp=300, tstamp=300}}, {{nla_len=8, nla_type=IFA_FLAGS}, IFA_F_PERMANENT}]}, {{len=72, type=RTM_NEWADDR, flags=NLM_F_MULTI, seq=1699052468, pid=788250}, {ifa_family=AF_INET6, ifa_prefixlen=64, ifa_flags=0, ifa_scope=RT_SCOPE_UNIVERSE, ifa_index=if_nametoindex("eth0")}, [{{nla_len=20, nla_type=IFA_ADDRESS}, inet_pton(AF_INET6, "<IPv6-Host-Address>")}, {{nla_len=20, nla_type=IFA_CACHEINFO}, {ifa_prefered=604768, ifa_valid=2591968, cstamp=8950, tstamp=4761889}}, {{nla_len=8, nla_type=IFA_FLAGS}, IFA_F_MANAGETEMPADDR|IFA_F_NOPREFIXROUTE}]}, {{len=72, type=RTM_NEWADDR, flags=NLM_F_MULTI, seq=1699052468, pid=788250}, {ifa_family=AF_INET6, ifa_prefixlen=64, ifa_flags=IFA_F_PERMANENT, ifa_scope=RT_SCOPE_UNIVERSE, ifa_index=if_nametoindex("eth0")}, [{{nla_len=20, nla_type=IFA_ADDRESS}, inet_pton(AF_INET6, "2a03:4000:4c:f8b:2845:c1ff:feba:3ea6")}, {{nla_len=20, nla_type=IFA_CACHEINFO}, {ifa_prefered=4294967295, ifa_valid=4294967295, cstamp=395, tstamp=395}}, {{nla_len=8, nla_type=IFA_FLAGS}, IFA_F_PERMANENT}]}, {{len=72, type=RTM_NEWADDR, flags=NLM_F_MULTI, seq=1699052468, pid=788250}, {ifa_family=AF_INET6, ifa_prefixlen=64, ifa_flags=IFA_F_PERMANENT, ifa_scope=RT_SCOPE_LINK, ifa_index=if_nametoindex("eth0")}, [{{nla_len=20, nla_type=IFA_ADDRESS}, inet_pton(AF_INET6, "fe80::2845:c1ff:feba:3ea6")}, {{nla_len=20, nla_type=IFA_CACHEINFO}, {ifa_prefered=4294967295, ifa_valid=4294967295, cstamp=384, tstamp=384}}, {{nla_len=8, nla_type=IFA_FLAGS}, IFA_F_PERMANENT}]}], iov_len=4096}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 288
788250 recvmsg(7, {msg_name={sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, msg_namelen=12, msg_iov=[{iov_base={{len=20, type=NLMSG_DONE, flags=NLM_F_MULTI, seq=1699052468, pid=788250}, 0}, iov_len=4096}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 20
788250 close(7) = 0
788250 socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC, IPPROTO_IP) = 7
788250 connect(7, {sa_family=AF_INET, sin_port=htons(0), sin_addr=inet_addr("142.250.186.106")}, 16) = 0
788250 getsockname(7, {sa_family=AF_INET, sin_port=htons(52419), sin_addr=inet_addr("<IPv4-Host-Address>")}, [28->16]) = 0
788250 close(7) = 0
788250 socket(AF_INET6, SOCK_DGRAM|SOCK_CLOEXEC, IPPROTO_IP) = 7
788250 connect(7, {sa_family=AF_INET6, sin6_port=htons(0), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "2a00:1450:4001:829::200a", &sin6_addr), sin6_scope_id=0}, 28) = 0
788250 getsockname(7, {sa_family=AF_INET6, sin6_port=htons(38608), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "<IPv6-Host-Address>", &sin6_addr), sin6_scope_id=0}, [28]) = 0
788250 close(7) = 0
788250 socket(AF_INET6, SOCK_STREAM, IPPROTO_IP) = 7
788250 fcntl(7, F_GETFL) = 0x2 (flags O_RDWR)
788250 fcntl(7, F_SETFL, O_RDWR|O_NONBLOCK) = 0
788250 connect(7, {sa_family=AF_INET6, sin6_port=htons(443), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "2a00:1450:4001:829::200a", &sin6_addr), sin6_scope_id=0}, 28) = -1 EINPROGRESS (Operation now in progress)
788250 poll([{fd=7, events=POLLIN|POLLOUT|POLLERR|POLLHUP}], 1, 60000 <unfinished ...>
788227 ptrace(PTRACE_ATTACH, 788250) = -1 EPERM (Operation not permitted)
788250 <... poll resumed>) = 0 (Timeout)
788250 fcntl(7, F_SETFL, O_RDWR) = 0
788250 close(7) = 0
[...]
Das PHP Skript fasst die /etc/resolv.conf
und die /etc/hosts
an, liest die Einträge dort und versucht via Localhost eine Domain von googleapis
aufzulösen und rennt in ein Timeout. Dies wird via IPv4 und IPv4 versucht. Zu erkennen ist das an folgenden Einträgen:
788250 stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=717, ...}) = 0
788250 openat(AT_FDCWD, "/etc/hosts", O_RDONLY|O_CLOEXEC) = 7
788250 sendmmsg(7, [{msg_hdr={msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\267\207\1 \0\1\0\0\0\0\0\1\5fonts\ngoogleapis\3co"..., iov_len=49}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, msg_len=49}, {msg_hdr={msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\22\204\1 \0\1\0\0\0\0\0\1\5fonts\ngoogleapis\3co"..., iov_len=49}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, msg_len=49}], 2, MSG_NOSIGNAL) = 2
788250 connect(7, {sa_family=AF_INET, sin_port=htons(0), sin_addr=inet_addr("142.250.186.106")}, 16) = 0
788250 getsockname(7, {sa_family=AF_INET, sin_port=htons(52419), sin_addr=inet_addr("<IPv4-Host-Address>")}, [28->16]) = 0
788250 connect(7, {sa_family=AF_INET6, sin6_port=htons(0), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "2a00:1450:4001:829::200a", &sin6_addr), sin6_scope_id=0}, 28) = 0
788250 getsockname(7, {sa_family=AF_INET6, sin6_port=htons(38608), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "<IPv6-Host-Address>", &sin6_addr), sin6_scope_id=0}, [28]) = 0
788250 poll([{fd=7, events=POLLIN|POLLOUT|POLLERR|POLLHUP}], 1, 60000 <unfinished ...>
788227 ptrace(PTRACE_ATTACH, 788250) = -1 EPERM (Operation not permitted)
788250 <... poll resumed>) = 0 (Timeout)
Ergo ist dies kein Anwendungsproblem mehr, sondern ein DNS/Netzwerk Problem. Ich konnte dies verifizieren. Weder über IPv4 noch über IPv6 konnte ich ein Ping an google.com rausschicken. Also setzte ich einen Nameserver und konnte somit via IPv4 ein Ping an Google senden. Was noch nicht ging war IPv6. Ich kam nie über den Switch von Netcup hinaus. Auch das direkte pingen von IPs war nicht möglich. Für meinen Test habe ich jetzt einfach IPv6 deaktiviert und einen Lieferschein erstellt. Jetzt rennt alles wieder.
Was aber nicht geklärt ist, wieso im laufeden Betrieb netcup ihr IPv6 Routing kaputt gemacht hat und es nach Tagen auch nicht mal gefixt hat und weshalb die VM einen fehlerhaften nameserver Eintrag hatte, so dass eine DomainauflÖsung nicht mehr stattfinden konnte? Dieser Laden ist echt frustrierend, dass dauernd etwas kaputt geht. Persönlich rate ich davon ab, bei netcup etwas zu hosten, außer es handelt sich um etwas vernachlässigbaren.