NC becomes unresponsive during WebDAV access

Hi guys. Hope anyone can help me with following issue.

Server: Notebook (Intel Core2Duo, 2 Gig RAM, 120 GB SSD, 4TB USB3.0, GBIT-Lan)
Nextcloud version: 16.0.3.0
Operating system and version: Debian 9
Apache or nginx version: Apache 2.4.38
PHP version : 7.3 (php-fpm)

The issue you are facing:

I try to stream (video-) files from Nextcloud via Samba (local) and WebDav (remote)
Samba works perfectly fine. The issue is about WebDav:

Connecting to the server and browsing files both work fine with WebDAV.
But once i start downloading / “streaming” files, nextcloud eventually becomes unresponsive. (Unresponsive = Stream freezes, and i cannot access nextcloud via web-browser either)

It sometimes happens after some minutes, Sometimes when starting to stream a file, cannot find a pattern. Server does not crash. After some time i can access normally.

CPU-load is at maximum ~80%
RAM-load is at maximum ~30%

I tried both Kodi (On android) and VLC Player (On windows) as clients. Same problem.
Cannot find real errors in the logs, so i started debugging apache.

Any idea what causes this, or how to further debug the error? (In PHP or somewhere?)

Is this the first time you’ve seen this error? (Y/N): No , tried it many times during the last week.

Steps to replicate it:

  1. Access files from Kodi or VLC via WebDav (remote)
  2. Start streaming a file
  3. Server becomes unresponsive after some time.

The output of your Nextcloud log in Admin > Logging:

NO ERRORS IN ADMIN LOGGING. 

The output of your config.php file in /path/to/nextcloud (make sure you remove any identifiable information!):

<?php
$CONFIG = array (
  'passwordsalt' => 'xxx',
  'secret' => 'xxx',
  'trusted_domains' => 
  array (
    0 => 'xxx',
    11 => 'xxx',
    1 => 'xxx',
    5 => 'nextcloudpi.local',
    7 => 'nextcloudpi',
    8 => 'nextcloudpi.lan',
    20 => 'xxx',
    4 => 'xxx',
  ),
  'datadirectory' => '/media/cloudstorage/nextcloud',
  'dbtype' => 'mysql',
  'version' => '16.0.3.0',
  'overwrite.cli.url' => 'xxx.ddns.net/',
  'dbname' => 'nextcloud',
  'dbhost' => 'localhost',
  'dbport' => '',
  'dbtableprefix' => 'oc_',
  'mysql.utf8mb4' => true,
  'dbuser' => 'xxx',
  'dbpassword' => 'xxx',
  'installed' => true,
  'instanceid' => 'xxx',
  'memcache.local' => '\\OC\\Memcache\\Redis',
  'memcache.locking' => '\\OC\\Memcache\\Redis',
  'redis' => 
  array (
    'host' => '/var/run/redis/redis.sock',
    'port' => 0,
    'timeout' => 0.0,
    'password' => 'xxxxxxx=',
  ),
  'tempdirectory' => '/media/cloudstorage/nextcloud/tmp',
  'mail_smtpmode' => 'sendmail',
  'mail_smtpauthtype' => 'LOGIN',
  'mail_from_address' => 'admin',
  'mail_domain' => 'ownyourbits.com',
  'preview_max_x' => '2048',
  'preview_max_y' => '2048',
  'jpeg_quality' => '60',
  'overwriteprotocol' => 'https',
  'debug' => true,
  'maintenance' => false,
  'logfile' => '/media/cloudstorage/nextcloud/nextcloud_new.log',
  'loglevel' => '2',
  'log_type' => 'file',
);

Syslog no errors / Kernel-log no errors / Apache-log no errors
So i started to debug the moment when the server becomes unresponsive

The output of your Apache/nginx/system log in /var/log/____:

First Time:


[Fri Sep 06 10:54:37.418399 2019] [http2:debug] [pid xxxx:tid xxxx62879232] h2_session.c(1138): [client xx.xx.xx.xx:yyyyy] AH03071: h2_stream(87-7,HALF_CLOSED_REMOTE): suspending
[Fri Sep 06 10:54:37.418978 2019] [http2:debug] [pid xxxx:tid xxxx62879232] h2_session.c(1541): [client xx.xx.xx.xx:yyyyy] AH02936: h2_stream(87-7,HALF_CLOSED_REMOTE): resumed
[Fri Sep 06 10:54:37.419023 2019] [http2:debug] [pid xxxx:tid xxxx62879232] h2_session.c(1541): [client xx.xx.xx.xx:yyyyy] AH02936: h2_stream(87-7,HALF_CLOSED_REMOTE): resumed
[Fri Sep 06 10:54:37.419204 2019] [http2:debug] [pid xxxx:tid xxxx62879232] h2_session.c(593): [client xx.xx.xx.xx:yyyyy] AH03068: h2_session(87,BUSY,1): sent FRAME[DATA[length=16375, flags=0, stream=7, padlen=0]], frames=8/1751 (r/s)
[Fri Sep 06 10:54:37.419266 2019] [http2:debug] [pid xxxx:tid xxxx62879232] h2_session.c(593): [client xx.xx.xx.xx:yyyyy] AH03068: h2_session(87,BUSY,1): sent FRAME[DATA[length=16375, flags=0, stream=7, padlen=0]], frames=8/1752 (r/s)
[Fri Sep 06 10:54:37.605668 2019] [http2:debug] [pid xxxx:tid xxxx62879232] h2_session.c(1541): [client xx.xx.xx.xx:yyyyy] AH02936: h2_stream(87-7,HALF_CLOSED_REMOTE): resumed
[Fri Sep 06 10:54:37.605755 2019] [http2:debug] [pid xxxx:tid xxxx62879232] h2_session.c(593): [client xx.xx.xx.xx:yyyyy] AH03068: h2_session(87,BUSY,1): sent FRAME[DATA[length=16375, flags=0, stream=7, padlen=0]], frames=8/1753 (r/s)
[Fri Sep 06 10:54:37.605796 2019] [http2:debug] [pid xxxx:tid xxxx62879232] h2_session.c(593): [client xx.xx.xx.xx:yyyyy] AH03068: h2_session(87,BUSY,1): sent FRAME[DATA[length=16375, flags=0, stream=7, padlen=0]], frames=8/1754 (r/s)
[Fri Sep 06 10:54:37.605861 2019] [http2:debug] [pid xxxx:tid xxxx62879232] h2_session.c(593): [client xx.xx.xx.xx:yyyyy] AH03068: h2_session(87,BUSY,1): sent FRAME[DATA[length=16375, flags=0, stream=7, padlen=0]], frames=8/1755 (r/s)
[Fri Sep 06 10:54:37.606174 2019] [http2:debug] [pid xxxx:tid xxxx62879232] h2_session.c(1541): [client xx.xx.xx.xx:yyyyy] AH02936: h2_stream(87-7,HALF_CLOSED_REMOTE): resumed
[Fri Sep 06 10:54:37.606209 2019] [http2:debug] [pid xxxx:tid xxxx62879232] h2_session.c(593): [client xx.xx.xx.xx:yyyyy] AH03068: h2_session(87,BUSY,1): sent FRAME[DATA[length=16375, flags=0, stream=7, padlen=0]], frames=8/1756 (r/s)
[Fri Sep 06 10:54:37.606242 2019] [http2:debug] [pid xxxx:tid xxxx62879232] h2_session.c(593): [client xx.xx.xx.xx:yyyyy] AH03068: h2_session(87,BUSY,1): sent FRAME[DATA[length=16375, flags=0, stream=7, padlen=0]], frames=8/1757 (r/s)
[Fri Sep 06 10:54:37.606454 2019] [http2:debug] [pid xxxx:tid xxxx62879232] h2_session.c(1541): [client xx.xx.xx.xx:yyyyy] AH02936: h2_stream(87-7,HALF_CLOSED_REMOTE): resumed
[Fri Sep 06 10:54:37.606485 2019] [http2:debug] [pid xxxx:tid xxxx62879232] h2_session.c(593): [client xx.xx.xx.xx:yyyyy] AH03068: h2_session(87,BUSY,1): sent FRAME[DATA[length=16375, flags=0, stream=7, padlen=0]], frames=8/1758 (r/s)
[Fri Sep 06 10:54:37.606514 2019] [http2:debug] [pid xxxx:tid xxxx62879232] h2_session.c(593): [client xx.xx.xx.xx:yyyyy] AH03068: h2_session(87,BUSY,1): sent FRAME[DATA[length=16375, flags=0, stream=7, padlen=0]], frames=8/1759 (r/s)
[Fri Sep 06 10:54:37.606543 2019] [http2:debug] [pid xxxx:tid xxxx62879232] h2_session.c(593): [client xx.xx.xx.xx:yyyyy] AH03068: h2_session(87,BUSY,1): sent FRAME[DATA[length=16375, flags=0, stream=7, padlen=0]], frames=8/1760 (r/s)
[Fri Sep 06 10:54:37.606837 2019] [http2:debug] [pid xxxx:tid xxxx62879232] h2_session.c(593): [client xx.xx.xx.xx:yyyyy] AH03068: h2_session(87,BUSY,1): sent FRAME[DATA[length=90, flags=0, stream=7, padlen=0]], frames=8/1761 (r/s)
[Fri Sep 06 10:54:37.606897 2019] [http2:debug] [pid xxxx:tid xxxx62879232] h2_session.c(1541): [client xx.xx.xx.xx:yyyyy] AH02936: h2_stream(87-7,HALF_CLOSED_REMOTE): resumed
[Fri Sep 06 10:54:37.606929 2019] [http2:debug] [pid xxxx:tid xxxx62879232] h2_session.c(1541): [client xx.xx.xx.xx:yyyyy] AH02936: h2_stream(87-7,HALF_CLOSED_REMOTE): resumed
[Fri Sep 06 10:54:37.606960 2019] [http2:debug] [pid xxxx:tid xxxx62879232] h2_session.c(1541): [client xx.xx.xx.xx:yyyyy] AH02936: h2_stream(87-7,HALF_CLOSED_REMOTE): resumed
[Fri Sep 06 10:54:37.606990 2019] [http2:debug] [pid xxxx:tid xxxx62879232] h2_session.c(1541): [client xx.xx.xx.xx:yyyyy] AH02936: h2_stream(87-7,HALF_CLOSED_REMOTE): resumed
[Fri Sep 06 10:54:37.607020 2019] [http2:debug] [pid xxxx:tid xxxx62879232] h2_session.c(593): [client xx.xx.xx.xx:yyyyy] AH03068: h2_session(87,BUSY,1): sent FRAME[DATA[length=16016, flags=0, stream=7, padlen=0]], frames=8/1762 (r/s)
[Fri Sep 06 10:54:37.607047 2019] [http2:debug] [pid xxxx:tid xxxx62879232] h2_session.c(593): [client xx.xx.xx.xx:yyyyy] AH03068: h2_session(87,BUSY,1): sent FRAME[DATA[length=16375, flags=0, stream=7, padlen=0]], frames=8/1763 (r/s)
[Fri Sep 06 10:54:37.607073 2019] [http2:debug] [pid xxxx:tid xxxx62879232] h2_session.c(593): [client xx.xx.xx.xx:yyyyy] AH03068: h2_session(87,BUSY,1): sent FRAME[DATA[length=16375, flags=0, stream=7, padlen=0]], frames=8/1764 (r/s)
[Fri Sep 06 10:54:55.466060 2019] [http2:debug] [pid xxxx:tid xxxx3782248192] h2_session.c(341): [client xx.xx.xx.xx:vvvvv] AH03066: h2_session(81,BUSY,1): recv FRAME[RST_STREAM[length=4, flags=0, stream=9]], frames=10/2726 (r/s)
[Fri Sep 06 10:54:55.466142 2019] [http2:debug] [pid xxxx:tid xxxx3782248192] h2_session.c(390): [client xx.xx.xx.xx:vvvvv] AH03067: h2_stream(81-9): RST_STREAM by client, errror=5
[Fri Sep 06 10:54:55.466193 2019] [http2:debug] [pid xxxx:tid xxxx3782248192] h2_session.c(267): [client xx.xx.xx.xx:vvvvv] AH03065: h2_stream(81-9,HALF_CLOSED_REMOTE): closing with err=5 stream closed

Second Time:


[Fri Sep 06 15:38:58.351636 2019] [http2:debug] [pid xxxx:tid xxxx75686448896] h2_session.c(593): [client xx:xx:xx:xx:yyyyy] AH03068: h2_session(16,BUSY,1): sent FRAME[DATA[length=1291, flags=0, stream=5, padlen=0]], frames=6/60 (r/s)
[Fri Sep 06 15:38:58.351658 2019] [http2:debug] [pid xxxx:tid xxxx75686448896] h2_session.c(593): [client xx:xx:xx:xx:yyyyy] AH03068: h2_session(16,BUSY,1): sent FRAME[DATA[length=1291, flags=0, stream=5, padlen=0]], frames=6/61 (r/s)
[Fri Sep 06 15:38:58.351679 2019] [http2:debug] [pid xxxx:tid xxxx75686448896] h2_session.c(593): [client xx:xx:xx:xx:yyyyy] AH03068: h2_session(16,BUSY,1): sent FRAME[DATA[length=1291, flags=0, stream=5, padlen=0]], frames=6/62 (r/s)
[Fri Sep 06 15:38:58.351701 2019] [http2:debug] [pid xxxx:tid xxxx75686448896] h2_session.c(593): [client xx:xx:xx:xx:yyyyy] AH03068: h2_session(16,BUSY,1): sent FRAME[DATA[length=1291, flags=0, stream=5, padlen=0]], frames=6/63 (r/s)
[Fri Sep 06 15:38:58.352232 2019] [http2:debug] [pid xxxx:tid xxxx75686448896] h2_session.c(593): [client xx:xx:xx:xx:yyyyy] AH03068: h2_session(16,BUSY,1): sent FRAME[DATA[length=493, flags=0, stream=5, padlen=0]], frames=6/64 (r/s)
[Fri Sep 06 15:38:58.352269 2019] [http2:debug] [pid xxxx:tid xxxx75686448896] h2_session.c(1138): [client xx:xx:xx:xx:yyyyy] AH03071: h2_stream(16-5,HALF_CLOSED_REMOTE): suspending
[Fri Sep 06 15:38:58.352644 2019] [proxy:debug] [pid xxxx:tid xxxx75941531392] proxy_util.c(2335): AH00943: FCGI: has released connection for (*)
[Fri Sep 06 15:38:58.352739 2019] [http2:debug] [pid xxxx:tid xxxx75686448896] h2_session.c(1541): [client xx:xx:xx:xx:yyyyy] AH02936: h2_stream(16-5,HALF_CLOSED_REMOTE): resumed
[Fri Sep 06 15:38:58.352767 2019] [http2:debug] [pid xxxx:tid xxxx75686448896] h2_session.c(593): [client xx:xx:xx:xx:yyyyy] AH03068: h2_session(16,BUSY,1): sent FRAME[DATA[length=1291, flags=0, stream=5, padlen=0]], frames=6/65 (r/s)
[Fri Sep 06 15:38:58.352789 2019] [http2:debug] [pid xxxx:tid xxxx75686448896] h2_session.c(593): [client xx:xx:xx:xx:yyyyy] AH03068: h2_session(16,BUSY,1): sent FRAME[DATA[length=1291, flags=0, stream=5, padlen=0]], frames=6/66 (r/s)
[Fri Sep 06 15:38:58.352826 2019] [http2:debug] [pid xxxx:tid xxxx75686448896] h2_session.c(593): [client xx:xx:xx:xx:yyyyy] AH03068: h2_session(16,BUSY,1): sent FRAME[DATA[length=1291, flags=0, stream=5, padlen=0]], frames=6/67 (r/s)
[Fri Sep 06 15:38:58.352849 2019] [http2:debug] [pid xxxx:tid xxxx75686448896] h2_session.c(593): [client xx:xx:xx:xx:yyyyy] AH03068: h2_session(16,BUSY,1): sent FRAME[DATA[length=401, flags=1, stream=5, padlen=0]], frames=6/68 (r/s)
[Fri Sep 06 15:38:58.352962 2019] [http2:debug] [pid xxxx:tid xxxx75686448896] h2_bucket_beam.c(1279): [client xx:xx:xx:xx:yyyyy] beam(19-5,output,closed=1,aborted=1,empty=1,buf=0): AH03385: h2_task_destroy, reuse slave
[Fri Sep 06 15:38:58.353045 2019] [http2:debug] [pid xxxx:tid xxxx75686448896] h2_session.c(1698): [client xx:xx:xx:xx:yyyyy] AH03078: h2_session(16,IDLE,0): transit [BUSY] -- no io (keepalive) --> [IDLE]
[Fri Sep 06 15:38:58.402836 2019] [http2:debug] [pid xxxx:tid xxxx75678056192] h2_session.c(341): [client xx:xx:xx:xx:yyyyy] AH03066: h2_session(16,IDLE,0): recv FRAME[RST_STREAM[length=4, flags=0, stream=5]], frames=6/68 (r/s)
[Fri Sep 06 15:38:58.402901 2019] [http2:debug] [pid xxxx:tid xxxx75678056192] h2_session.c(390): [client xx:xx:xx:xx:yyyyy] AH03067: h2_stream(16-5): RST_STREAM by client, errror=5
[Fri Sep 06 15:39:03.404719 2019] [http2:debug] [pid xxxx:tid xxxx75661270784] h2_session.c(593): [client xx:xx:xx:xx:yyyyy] AH03068: h2_session(16,IDLE,0): sent FRAME[GOAWAY[error=0, reason='timeout', last_stream=5]], frames=7/69 (r/s)
[Fri Sep 06 15:39:03.405005 2019] [http2:debug] [pid xxxx:tid xxxx75661270784] h2_session.c(753): [client xx:xx:xx:xx:yyyyy] AH03069: h2_session(16,IDLE,0): sent GOAWAY, err=0, msg=timeout
[Fri Sep 06 15:39:03.405057 2019] [http2:debug] [pid xxxx:tid xxxx75661270784] h2_session.c(1698): [client xx:xx:xx:xx:yyyyy] AH03078: h2_session(16,DONE,0): transit [IDLE] -- local goaway --> [DONE]
[Fri Sep 06 15:39:03.405093 2019] [http2:debug] [pid xxxx:tid xxxx75661270784] h2_session.c(1698): [client xx:xx:xx:xx:yyyyy] AH03078: h2_session(16,CLEANUP,0): transit [DONE] -- pre_close --> [CLEANUP]
[Fri Sep 06 15:39:03.405514 2019] [ssl:debug] [pid xxxx:tid xxxx75661270784] ssl_engine_io.c(1106): [client xx:xx:xx:xx:yyyyy] AH02001: Connection closed to child 22 with standard shutdown (server xxxx.ddns.net:443)
[Fri Sep 06 15:39:06.416048 2019] [ssl:info] [pid xxxx:tid xxxx75916353280] [client xx:xx:xx:xx::2001] AH01964: Connection to child 0 established (server xxxx.ddns.net:443)
[Fri Sep 06 15:39:06.416680 2019] [socache_shmcb:debug] [pid xxxx:tid xxxx75916353280] mod_socache_shmcb.c(532): AH00835: socache_shmcb_retrieve (0x90 -> subcache 16)
[Fri Sep 06 15:39:06.416740 2019] [socache_shmcb:debug] [pid xxxx:tid xxxx75916353280] mod_socache_shmcb.c(884): AH00849: match at idx=0, data=0
[Fri Sep 06 15:39:06.416773 2019] [socache_shmcb:debug] [pid xxxx:tid xxxx75916353280] mod_socache_shmcb.c(542): AH00836: leaving socache_shmcb_retrieve successfully
[Fri Sep 06 15:39:06.416881 2019] [ssl:debug] [pid xxxx:tid xxxx75916353280] ssl_engine_kernel.c(2319): [client xx:xx:xx:xx::2001] AH02043: SSL virtual host for servername xxxx.ddns.net found
[Fri Sep 06 15:39:06.416975 2019] [ssl:debug] [pid xxxx:tid xxxx75916353280] ssl_engine_kernel.c(2319): [client xx:xx:xx:xx::2001] AH02043: SSL virtual host for servername xxxx.ddns.net found
[Fri Sep 06 15:39:06.417014 2019] [core:debug] [pid xxxx:tid xxxx75916353280] protocol.c(2314): [client xx:xx:xx:xx::2001] AH03155: select protocol from h2,h2c,http/1.1,h2,h2c,http/1.1, choices=h2,http/1.1 for server xxxx.ddns.net
[Fri Sep 06 15:39:06.417067 2019] [core:debug] [pid xxxx:tid xxxx75916353280] protocol.c(2359): [client xx:xx:xx:xx::2001] AH03156: select protocol, proposals=h2,http/1.1 preferences=h2,h2c,http/1.1,h2,h2c,http/1.1 configured=h2,h2c,http/1.1,h2,h2c,http/1.1
[Fri Sep 06 15:39:06.417102 2019] [core:debug] [pid xxxx:tid xxxx75916353280] protocol.c(2377): [client xx:xx:xx:xx::2001] AH03157: selected protocol=h2
[Fri Sep 06 15:39:06.449031 2019] [ssl:debug] [pid xxxx:tid xxxx75916353280] ssl_engine_kernel.c(2235): [client xx:xx:xx:xx::2001] AH02041: Protocol: TLSv1.2, Cipher: ECDHE-RSA-CHACHA20-POLY1305 (256/256 bits)
[Fri Sep 06 15:39:06.449281 2019] [http2:debug] [pid xxxx:tid xxxx75916353280] h2_session.c(958): [client xx:xx:xx:xx::2001] AH03200: h2_session(0,INIT,0): created, max_streams=100, stream_mem=32768, workers_limit=6, workers_max=37, push_diary(type=1,N=256)
[Fri Sep 06 15:39:06.449323 2019] [http2:debug] [pid xxxx:tid xxxx75916353280] h2_session.c(1040): [client xx:xx:xx:xx::2001] AH03201: h2_session(0,INIT,0): start, INITIAL_WINDOW_SIZE=65535, MAX_CONCURRENT_STREAMS=100
[Fri Sep 06 15:39:06.449346 2019] [http2:debug] [pid xxxx:tid xxxx75916353280] h2_session.c(2134): [client xx:xx:xx:xx::2001] AH03079: h2_session(0,INIT,0): started on xxxx.ddns.net:443
[Fri Sep 06 15:39:06.449363 2019] [http2:debug] [pid xxxx:tid xxxx75916353280] h2_session.c(1698): [client xx:xx:xx:xx::2001] AH03078: h2_session(0,BUSY,0): transit [INIT] -- init --> [BUSY]
[Fri Sep 06 15:39:06.449496 2019] [http2:debug] [pid xxxx:tid xxxx75916353280] h2_session.c(341): [client xx:xx:xx:xx::2001] AH03066: h2_session(0,BUSY,0): recv FRAME[SETTINGS[length=18, stream=0]], frames=0/0 (r/s)
[Fri Sep 06 15:39:06.449550 2019] [http2:debug] [pid xxxx:tid xxxx75916353280] h2_session.c(341): [client xx:xx:xx:xx::2001] AH03066: h2_session(0,BUSY,0): recv FRAME[WINDOW_UPDATE[stream=0, incr=1073676289]], frames=1/0 (r/s)
[Fri Sep 06 15:39:06.449589 2019] [http2:debug] [pid xxxx:tid xxxx75916353280] h2_session.c(593): [client xx:xx:xx:xx::2001] AH03068: h2_session(0,BUSY,0): sent FRAME[SETTINGS[length=6, stream=0]], frames=2/1 (r/s)
[Fri Sep 06 15:39:06.449613 2019] [http2:debug] [pid xxxx:tid xxxx75916353280] h2_session.c(593): [client xx:xx:xx:xx::2001] AH03068: h2_session(0,BUSY,0): sent FRAME[SETTINGS[XXX=1, stream=0]], frames=2/2 (r/s)
[Fri Sep 06 15:39:06.449632 2019] [http2:debug] [pid xxxx:tid xxxx75916353280] h2_session.c(593): [client xx:xx:xx:xx::2001] AH03068: h2_session(0,BUSY,0): sent FRAME[WINDOW_UPDATE[stream=0, incr=2147418112]], frames=2/3 (r/s)
[Fri Sep 06 15:39:06.449730 2019] [http2:debug] [pid xxxx:tid xxxx75916353280] h2_session.c(1698): [client xx:xx:xx:xx::2001] AH03078: h2_session(0,IDLE,0): transit [BUSY] -- no io (keepalive) --> [IDLE]
[Fri Sep 06 15:39:06.456565 2019] [http2:debug] [pid xxxx:tid xxxx75916353280] h2_stream.c(543): [client xx:xx:xx:xx::2001] AH03082: h2_stream(0-1,IDLE): created
[Fri Sep 06 15:39:06.456631 2019] [http2:debug] [pid xxxx:tid xxxx75916353280] h2_session.c(1698): [client xx:xx:xx:xx::2001] AH03078: h2_session(0,BUSY,1): transit [IDLE] -- stream change --> [BUSY]
[Fri Sep 06 15:39:06.456702 2019] [http2:debug] [pid xxxx:tid xxxx75916353280] h2_session.c(341): [client xx:xx:xx:xx::2001] AH03066: h2_session(0,BUSY,1): recv FRAME[HEADERS[length=465, hend=1, stream=1, eos=1]], frames=2/3 (r/s)
[Fri Sep 06 15:39:06.456924 2019] [ssl:debug] [pid xxxx:tid xxxx75941531392] ssl_engine_kernel.c(383): [client xx:xx:xx:xx::2001] AH02034: Subsequent (No.2) HTTPS request received for child 1 (server xxxx.ddns.net:443)
[Fri Sep 06 15:39:06.457661 2019] [authz_core:debug] [pid xxxx:tid xxxx75941531392] mod_authz_core.c(820): [client xx:xx:xx:xx::2001] AH01626: authorization result of Require all granted: granted
[Fri Sep 06 15:39:06.457685 2019] [authz_core:debug] [pid xxxx:tid xxxx75941531392] mod_authz_core.c(820): [client xx:xx:xx:xx::2001] AH01626: authorization result of <RequireAny>: granted
[Fri Sep 06 15:39:06.457745 2019] [proxy:debug] [pid xxxx:tid xxxx75941531392] mod_proxy.c(1248): [client xx:xx:xx:xx::2001] AH01143: Running scheme unix handler (attempt 0)
[Fri Sep 06 15:39:06.457763 2019] [proxy_fcgi:debug] [pid xxxx:tid xxxx75941531392] mod_proxy_fcgi.c(1021): [client xx:xx:xx:xx::2001] AH01076: url: fcgi://localhost/var/www/nextcloud/remote.php proxyname: (null) proxyport: 0
[Fri Sep 06 15:39:06.457797 2019] [proxy_fcgi:debug] [pid xxxx:tid xxxx75941531392] mod_proxy_fcgi.c(1028): [client xx:xx:xx:xx::2001] AH01078: serving URL fcgi://localhost/var/www/nextcloud/remote.php
[Fri Sep 06 15:39:06.457815 2019] [proxy:debug] [pid xxxx:tid xxxx75941531392] proxy_util.c(2320): AH00942: FCGI: has acquired connection for (*)
[Fri Sep 06 15:39:06.457833 2019] [proxy:debug] [pid xxxx:tid xxxx75941531392] proxy_util.c(2373): [client xx:xx:xx:xx::2001] AH00944: connecting fcgi://localhost/var/www/nextcloud/remote.php to localhost:8000
[Fri Sep 06 15:39:06.457849 2019] [proxy:debug] [pid xxxx:tid xxxx75941531392] proxy_util.c(2410): [client xx:xx:xx:xx::2001] AH02545: fcgi: has determined UDS as /run/php/php7.3-fpm.sock
[Fri Sep 06 15:39:06.457986 2019] [proxy:debug] [pid xxxx:tid xxxx75941531392] proxy_util.c(2582): [client xx:xx:xx:xx::2001] AH00947: connected /var/www/nextcloud/remote.php to httpd-UDS:0
[Fri Sep 06 15:39:06.458030 2019] [proxy:debug] [pid xxxx:tid xxxx75941531392] proxy_util.c(2953): AH02823: FCGI: connection established with Unix domain socket /run/php/php7.3-fpm.sock (*)
[Fri Sep 06 15:39:06.458148 2019] [authz_core:debug] [pid xxxx:tid xxxx75941531392] mod_authz_core.c(820): [client xx:xx:xx:xx::2001] AH01626: authorization result of Require all granted: granted
[Fri Sep 06 15:39:06.458166 2019] [authz_core:debug] [pid xxxx:tid xxxx75941531392] mod_authz_core.c(820): [client xx:xx:xx:xx::2001] AH01626: authorization result of <RequireAny>: granted
[Fri Sep 06 15:39:06.478775 2019] [http2:debug] [pid xxxx:tid xxxx75916353280] h2_session.c(341): [client xx:xx:xx:xx::2001] AH03066: h2_session(0,BUSY,1): recv FRAME[SETTINGS[XXX=1, stream=0]], frames=3/3 (r/s)
[Fri Sep 06 15:39:06.547580 2019] [proxy:debug] [pid xxxx:tid xxxx75941531392] proxy_util.c(2335): AH00943: FCGI: has released connection for (*)
[Fri Sep 06 15:39:06.547661 2019] [http2:debug] [pid xxxx:tid xxxx75941531392] h2_task.c(87): [client xx:xx:xx:xx::2001] AH03348: h2_task(0-1): open output to PROPFIND xxxx.ddns.net /remote.php/webdav/
[Fri Sep 06 15:39:06.547780 2019] [http2:debug] [pid xxxx:tid xxxx75916353280] h2_session.c(1387): [client xx:xx:xx:xx::2001] AH03073: h2_stream(0-1,HALF_CLOSED_REMOTE): submit response 207, REMOTE_WINDOW_SIZE=1073741824
[Fri Sep 06 15:39:06.547818 2019] [http2:debug] [pid xxxx:tid xxxx75916353280] h2_session.c(1541): [client xx:xx:xx:xx::2001] AH02936: h2_stream(0-1,HALF_CLOSED_REMOTE): resumed
[Fri Sep 06 15:39:06.547872 2019] [http2:debug] [pid xxxx:tid xxxx75916353280] h2_session.c(593): [client xx:xx:xx:xx::2001] AH03068: h2_session(0,BUSY,1): sent FRAME[HEADERS[length=383, hend=1, stream=1, eos=0]], frames=4/4 (r/s)
[Fri Sep 06 15:39:06.547903 2019] [http2:debug] [pid xxxx:tid xxxx75916353280] h2_session.c(593): [client xx:xx:xx:xx::2001] AH03068: h2_session(0,BUSY,1): sent FRAME[DATA[length=1291, flags=0, stream=1, padlen=0]], frames=4/5 (r/s)
[Fri Sep 06 15:39:06.547926 2019] [http2:debug] [pid xxxx:tid xxxx75916353280] h2_session.c(593): [client xx:xx:xx:xx::2001] AH03068: h2_session(0,BUSY,1): sent FRAME[DATA[length=1291, flags=0, stream=1, padlen=0]], frames=4/6 (r/s)
[Fri Sep 06 15:39:06.547949 2019] [http2:debug] [pid xxxx:tid xxxx75916353280] h2_session.c(593): [client xx:xx:xx:xx::2001] AH03068: h2_session(0,BUSY,1): sent FRAME[DATA[length=148, flags=1, stream=1, padlen=0]], frames=4/7 (r/s)
[Fri Sep 06 15:39:06.548086 2019] [http2:debug] [pid xxxx:tid xxxx75916353280] h2_bucket_beam.c(1279): [client xx:xx:xx:xx::2001] beam(0-1,output,closed=1,aborted=1,empty=1,buf=0): AH03385: h2_task_destroy, reuse slave
[Fri Sep 06 15:39:06.548194 2019] [http2:debug] [pid xxxx:tid xxxx75916353280] h2_session.c(1698): [client xx:xx:xx:xx::2001] AH03078: h2_session(0,IDLE,0): transit [BUSY] -- no io (keepalive) --> [IDLE]
[Fri Sep 06 15:39:12.552651 2019] [http2:debug] [pid xxxx:tid xxxx75907960576] h2_session.c(593): [client xx:xx:xx:xx::2001] AH03068: h2_session(0,IDLE,0): sent FRAME[GOAWAY[error=0, reason='timeout', last_stream=1]], frames=4/8 (r/s)
[Fri Sep 06 15:39:12.552944 2019] [http2:debug] [pid xxxx:tid xxxx75907960576] h2_session.c(753): [client xx:xx:xx:xx::2001] AH03069: h2_session(0,IDLE,0): sent GOAWAY, err=0, msg=timeout
[Fri Sep 06 15:39:12.553009 2019] [http2:debug] [pid xxxx:tid xxxx75907960576] h2_session.c(1698): [client xx:xx:xx:xx::2001] AH03078: h2_session(0,DONE,0): transit [IDLE] -- local goaway --> [DONE]
[Fri Sep 06 15:39:12.553045 2019] [http2:debug] [pid xxxx:tid xxxx75907960576] h2_session.c(1698): [client xx:xx:xx:xx::2001] AH03078: h2_session(0,CLEANUP,0): transit [DONE] -- pre_close --> [CLEANUP]
[Fri Sep 06 15:39:12.553393 2019] [ssl:debug] [pid xxxx:tid xxxx75907960576] ssl_engine_io.c(1106): [client xx:xx:xx:xx::2001] AH02001: Connection closed to child 1 with standard shutdown (server xxxx.ddns.net:443)