Plné /tmp/ -> různé věci jsou rozbité

Nefunguje mi UI na Forrisu i Luci, na obou:

Unhandled Exception

An unhandled exception was thrown by the application.

Nefunguje kresd, při startu:
chown: unknown user/group kresd:kresd

Co se stalo?

/tmp je úplně plné, co můžu bezpečně smazat?

Aha, tak kresd nefunguje jen kvůli plnému /tmp. Je v RAM, takže bych to “jednorázově/nouzově” řešil restartem routeru, to je nejjednodušší.

1 Like

Tohle je známá neškodná hláška která by brzy měla zmizet.

Předpokládám že i ostatní problémy jsou jen důsledkem plného /tmp. To tedy neřeší jak k zaplnění došlo, pár vláken tady na fóru bylo…

2 Likes

Všechno se to opravilo uvpolněním /tmp, updatem a restartem služeb.
Ale jednou za den mi přestane fungovat kresd a musím ho restartovat.

U kresd nám většinou stačí k identifikaci problému získat rozšířené výpisy okolo chybového momentu, například podle návodu (předpokládám že angličtina nevadí). Mimochodem, některé potíže byly řešeny v čerstvě vydaném Turris OS 3.11.2.

Zkusil jsem zapnout DNS debug. Problém se děje každý den.

Mohl by se mi k tomu někdo vyjádřit?

Messages jinak vypadá následovně, někdy v průběhu se to stalo, na konci je hláška, že nezafungoval dyndsn, protože už resolving nejel:

2019-01-21 00:12:31 info dnsmasq-dhcp[9671]: DHCPOFFER(br-lan) 10.9.8.195 70:85:c2:6a:d2:5a
2019-01-21 00:13:01 info /usr/sbin/cron[28557]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2019-01-21 00:13:18 info hostapd: wlan0: STA a4:4e:31:1b:05:00 WPA: group key handshake completed (RSN)
2019-01-21 00:13:18 info hostapd: wlan0: STA 6c:88:14:6c:9b:40 WPA: group key handshake completed (RSN)
2019-01-21 00:13:18 info hostapd: wlan0: STA cc:fd:17:e7:13:e6 WPA: group key handshake completed (RSN)
2019-01-21 00:13:18 info hostapd: wlan0: STA 60:88:4b:59:16:9e WPA: group key handshake completed (RSN)
2019-01-21 00:13:26 info hostapd: wlan1: STA d0:73:d5:01:b4:c5 WPA: group key handshake completed (RSN)
2019-01-21 00:13:26 info hostapd: wlan1: STA b8:27:eb:06:8b:06 WPA: group key handshake completed (RSN)
2019-01-21 00:13:26 info hostapd: wlan1: STA 00:13:ef:d0:23:3c WPA: group key handshake completed (RSN)
2019-01-21 00:13:36 info dnsmasq-dhcp[9671]: DHCPDISCOVER(br-lan) 70:85:c2:6a:d2:5a
2019-01-21 00:13:36 info dnsmasq-dhcp[9671]: DHCPOFFER(br-lan) 10.9.8.195 70:85:c2:6a:d2:5a
2019-01-21 00:14:01 info /usr/sbin/cron[28640]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2019-01-21 00:14:01 info /usr/sbin/cron[28641]: (root) CMD (nethist_stats.lua)
2019-01-21 00:14:40 info dnsmasq-dhcp[9671]: DHCPDISCOVER(br-lan) 70:85:c2:6a:d2:5a
2019-01-21 00:14:40 info dnsmasq-dhcp[9671]: DHCPOFFER(br-lan) 10.9.8.195 70:85:c2:6a:d2:5a
2019-01-21 00:15:01 info /usr/sbin/cron[28726]: (root) CMD ( /usr/bin/notifier)
2019-01-21 00:15:01 info /usr/sbin/cron[28725]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2019-01-21 00:15:01 info /usr/sbin/cron[28727]: (root) CMD (/usr/share/nikola/bin/nikola.sh)
2019-01-21 00:15:03 info nikola: (v43) recognized WAN interfaces: eth1, lo
2019-01-21 00:15:44 info dnsmasq-dhcp[9671]: DHCPDISCOVER(br-lan) 70:85:c2:6a:d2:5a
2019-01-21 00:15:44 info dnsmasq-dhcp[9671]: DHCPOFFER(br-lan) 10.9.8.195 70:85:c2:6a:d2:5a
2019-01-21 00:15:53 info nikola: (v43) Establishing connection took 0.509020 seconds
2019-01-21 00:15:53 info nikola: (v43) Logrotate took 0.006144 seconds
2019-01-21 00:15:53 info nikola: (v43) Syslog parsing took 0.392516 seconds
2019-01-21 00:15:54 info nikola: (v43) Session init took 0.625496 seconds
2019-01-21 00:15:54 info nikola: (v43) Records parsed: 466
2019-01-21 00:15:54 info nikola: (v43) Records after filtering: 466
2019-01-21 00:15:54 info nikola: (v43) Records filtering took 0.045516 seconds
2019-01-21 00:15:54 info nikola: (v43) {‘msg’: ‘Data were inserted into work queue.’}
2019-01-21 00:15:54 info nikola: (v43) Sending records took 0.027264 seconds
2019-01-21 00:16:01 info /usr/sbin/cron[28866]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2019-01-21 00:16:01 info /usr/sbin/cron[28867]: (root) CMD (nethist_stats.lua)
2019-01-21 00:16:47 info dnsmasq-dhcp[9671]: DHCPDISCOVER(br-lan) 70:85:c2:6a:d2:5a
2019-01-21 00:16:47 info dnsmasq-dhcp[9671]: DHCPOFFER(br-lan) 10.9.8.195 70:85:c2:6a:d2:5a
2019-01-21 00:17:01 info /usr/sbin/cron[28951]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2019-01-21 00:17:51 info dnsmasq-dhcp[9671]: DHCPDISCOVER(br-lan) 70:85:c2:6a:d2:5a
2019-01-21 00:17:51 info dnsmasq-dhcp[9671]: DHCPOFFER(br-lan) 10.9.8.195 70:85:c2:6a:d2:5a
2019-01-21 00:18:01 info /usr/sbin/cron[29035]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2019-01-21 00:18:01 info /usr/sbin/cron[29034]: (root) CMD (nethist_stats.lua)
2019-01-21 00:18:56 info dnsmasq-dhcp[9671]: DHCPDISCOVER(br-lan) 70:85:c2:6a:d2:5a
2019-01-21 00:18:56 info dnsmasq-dhcp[9671]: DHCPOFFER(br-lan) 10.9.8.195 70:85:c2:6a:d2:5a
2019-01-21 00:19:01 info /usr/sbin/cron[29121]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2019-01-21 00:19:59 info dnsmasq-dhcp[9671]: DHCPDISCOVER(br-lan) 70:85:c2:6a:d2:5a
2019-01-21 00:19:59 info dnsmasq-dhcp[9671]: DHCPOFFER(br-lan) 10.9.8.195 70:85:c2:6a:d2:5a
2019-01-21 00:20:01 info /usr/sbin/cron[29207]: (root) CMD ( /usr/bin/notifier)
2019-01-21 00:20:01 info /usr/sbin/cron[29209]: (root) CMD (nethist_stats.lua)
2019-01-21 00:20:01 info /usr/sbin/cron[29208]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2019-01-21 00:21:01 info /usr/sbin/cron[29322]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2019-01-21 00:21:02 info dnsmasq-dhcp[9671]: DHCPDISCOVER(br-lan) 70:85:c2:6a:d2:5a
2019-01-21 00:21:02 info dnsmasq-dhcp[9671]: DHCPOFFER(br-lan) 10.9.8.195 70:85:c2:6a:d2:5a
2019-01-21 00:22:01 info /usr/sbin/cron[29406]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2019-01-21 00:22:01 info /usr/sbin/cron[29405]: (root) CMD (nethist_stats.lua)
2019-01-21 00:22:06 info dnsmasq-dhcp[9671]: DHCPDISCOVER(br-lan) 70:85:c2:6a:d2:5a
2019-01-21 00:22:06 info dnsmasq-dhcp[9671]: DHCPOFFER(br-lan) 10.9.8.195 70:85:c2:6a:d2:5a
2019-01-21 00:22:57 err ddns-scripts[2574]: new: BusyBox nslookup error: 1
2019-01-21 00:22:57 warning ddns-scripts[2574]: new: Get registered/public IP for int.shy.cz failed - retry 1/0 in 60 seconds

V těchto výpisech není z kresd ani řádek. Předpokládám že jste nečekal, že “Start resolver debugging” je zrušeno změnou konfigurace DNS nebo restartem.

Vyzkouším znovu, můžu ověřit, že je debugging zapnutý?

Nemělo by kresd produkovat nějakou hlášku samo o sobě, když přestane fungovat DNS resolving?

Nejjednodušší bude se do logu podívat. Každý DNS dotaz by měl produkovat vícero řádek obsahujících kresd, mnohdy i desítky.

“přestane fungovat DNS resolving”… no nemám představu v jaké situaci přesně by to mělo logovat. Existují například domény které jsou záměrně rozbité – třeba jednoduché webové testy “podpory DNSSEC” většinou dělají to, že zkouší resolvovat doménu s rozbitým DNSSEC, což má selhat.

Mám úplně stejný problém. Bez občasného restartu nefunguje DNS resolving.
V log messages se mi zda divne toto:
2019-01-31 17:35:10 info kresd[3432]: > [ ta ] key: 19036 state: Missing
2019-01-31 17:35:10 info kresd[3432]: [ ta ] key: 20326 state: Valid
2019-01-31 17:35:10 info kresd[3432]: [ ta ] next refresh for . in 1 hours
Hlavne ten refresh rate mi prijde podezrely. Cca to odpovida.

Tohle je celkem standardní log při startu kresd. Někteří tedy teď budou mít klíč 19036 v “Revoked” stavu a v některých distribucích již zcela odebraný, ale všechny tři případy by měly být bezproblémové. (Je to starý klíč který byl odrotován.)

1 Like

Tedy pokud “stejný problém” znamená že máte plné /tmp, tak taková věc typicky DNS rozbije, ale důvod plného /tmp zatím nikdy v DNS neležel (cache je omezena na 20 MB).

1 Like

Ano pruvodnim jevem je plne /tmp.
Michal Smolak

Pri plnem /tmp nefubguje forris.

Error | Administration interface of router Turris body, html {background-color: #eee; font-family: Helvetica, Arial, sans-serif;} #page {background-color: #fff; border: 1px solid #ccc; margin: 0 auto; padding: 1em; min-width: 60em; width: 90%;} hr {border: 0; color: #999; background-color: #999; height: 1px;} p {line-height: 160%;} pre {background-color: #fef9df; border: 1px solid #999; padding: 1em; margin: 1em;} .error {color: #c00;}

An unexpected error has occurred

    <p>We are sorry, but your request raised an unexpected error. More information about this error may be found below.</p>
    <p>If you are willing to help us with fixing of the problem, download the following <a href="/foris/config/foris-error.html">error protocol</a> and send it to us with a short description of the steps that led to the error to our email address <a href="mailto:tech.support@turris.cz">tech.support@turris.cz</a> (the protocol contains only a copy of the following informations).</p>
    <hr>

    <h1>Při zpracování požadavku došlo k chybě</h1>

    <p>Omlouváme se, ale během zpracování Vašeho požadavku došlo k nečekané chybě. Detailní informace naleznete níže.</p>
    <p>Pokud nám chcete pomoci s odstraněním chyby, stáhněte následující <a href="/foris/config/foris-error.html">protokol o chybě</a> a zašlete nám jej s krátkým popisem okolností vzniku chyby na adresu <a href="mailto:tech.support@turris.cz">tech.support@turris.cz</a> (protokol obsahuje pouze kopii informací uvedených na této stránce).</p>
    <hr>

    <h2 class="error">Remote Exception: Incorrect output. {&#039;kind&#039;: &#039;reply&#039;, &#039;module&#039;: &#039;router_notifications&#039;, &#039;action&#039;: &#039;list&#039;, &#039;data&#039;: {&#039;notifications&#039;: [{&#039;id&#039;: &#039;1548961351-9924&#039;, &#039;displayed&#039;: False, &#039;severity&#039;: &#039;&#039;, &#039;created_at&#039;: &#039;2019-01-31T20:02:31&#039;, &#039;msg&#039;: &#039;&#039;, &#039;lang&#039;: &#039;cs&#039;}]}}</h2>
    <h3>Remote request</h3><pre>{&quot;module&quot;: &quot;router_notifications&quot;, &quot;action&quot;: &quot;list&quot;, &quot;kind&quot;: &quot;request&quot;, &quot;data&quot;: {&quot;lang&quot;: &quot;cs&quot;}}</pre>
    <h3>Stack trace</h3>
    <pre>Traceback (most recent call last):

File "/usr/lib/python3.6/site-packages/foris_controller/message_router.py", line 132, in process_message
self.validate(reply)
File "/usr/lib/python3.6/site-packages/foris_controller/message_router.py", line 40, in wrapper
res = function(*args, **kwargs)
File "/usr/lib/python3.6/site-packages/foris_controller/message_router.py", line 74, in validate
app_info["validator"].validate(message)
File "/usr/lib/python3.6/site-packages/foris_schema/validator.py", line 257, in validate
Draft4Validator(mini_schema, format_checker=FormatChecker()).validate(msg)
File "/usr/lib/python3.6/site-packages/jsonschema/validators.py", line 130, in validate
raise error
jsonschema.exceptions.ValidationError: '' is not one of ['news', 'restart', 'error', 'update']

Failed validating 'enum' in schema['properties']['data']['properties']['notifications']['items']['properties']['severity']:
{'enum': ['news', 'restart', 'error', 'update']}

On instance['data']['notifications'][0]['severity']:
''

Environment


{'CONTENT_LENGTH': '0',
'DOCUMENT_ROOT': '/www',
'GATEWAY_INTERFACE': 'CGI/1.1',
'HTTPS': 'on',
'HTTP_ACCEPT': 'text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,/;q=0.8',
'HTTP_ACCEPT_ENCODING': 'gzip, deflate, br',
'HTTP_ACCEPT_LANGUAGE': 'cs,en-US;q=0.7,en;q=0.3',
'HTTP_CONNECTION': 'keep-alive',
'HTTP_COOKIE': 'foris.ws.session=556cf30f75f6ea4f1c97fa90fa2abe5e; '
'beaker.session.id=abb9c146ebba4e529487bf77c35245d2; '
'foris.session=ba678279753e51adc43a0feda61e8efc',
'HTTP_DNT': '1',
'HTTP_HOST': '192.168.1.1',
'HTTP_REFERER': 'https://192.168.1.1/foris/config/',
'HTTP_UPGRADE_INSECURE_REQUESTS': '1',
'HTTP_USER_AGENT': 'Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:65.0) '
'Gecko/20100101 Firefox/65.0',
'PATH_INFO': '/main/notifications/',
'PATH_TRANSLATED': '/www/main/notifications/',
'QUERY_STRING': '',
'REDIRECT_STATUS': '200',
'REMOTE_ADDR': '192.168.1.219',
'REMOTE_PORT': '43124',
'REQUEST_METHOD': 'GET',
'REQUEST_SCHEME': 'https',
'REQUEST_URI': '/foris/config/main/notifications/',
'SCRIPT_FILENAME': '/www/foris/config',
'SCRIPT_NAME': '/foris/config',
'SERVER_ADDR': '192.168.1.1',
'SERVER_NAME': '192.168.1.1',
'SERVER_PORT': '443',
'SERVER_PROTOCOL': 'HTTP/1.1',
'SERVER_SOFTWARE': 'lighttpd/1.4.50',
'SSL_CIPHER': 'ECDHE-RSA-AES128-GCM-SHA256',
'SSL_CIPHER_ALGKEYSIZE': '128',
'SSL_CIPHER_USEKEYSIZE': '128',
'SSL_PROTOCOL': 'TLSv1.2',
'bottle.app': <bottle.Bottle object at 0x1e5d960>,
'bottle.raw_path': '/notifications/',
'bottle.request': <LocalRequest: GET https://192.168.1.1/foris/config/main/notifications/>,
'bottle.request.urlparts': SplitResult(scheme='https', netloc='192.168.1.1', path='/foris/config/main/notifications/', query='', fragment=''),
'bottle.route': <GET '/<page_name:re:.+>/' <function config_page_get at 0x1e56cf0>>,
'foris.backend': UbusSender('/var/run/ubus.sock'),
'foris.language': 'cs',
'foris.session': <foris.middleware.sessions.SessionForisProxy object at 0x1f90de0>,
'foris.session.data': {'csrf_token': 'e5mB7LWtxVfvSevsNxmmCFOtpiLx1JdK',
'user_authenticated': True},
'foris.session.id': 'ba678279753e51adc43a0feda61e8efc',
'foris.version': '99.1',
'route.handle': <GET '/<page_name:re:.+>/' <function config_page_get at 0x1e56cf0>>,
'route.url_args': {'page_name': 'notifications'},
'wsgi.errors': <flup.server.fcgi_base.OutputStream object at 0x1f0f680>,
'wsgi.input': <flup.server.fcgi_base.InputStream object at 0x1f72630>,
'wsgi.multiprocess': False,
'wsgi.multithread': True,
'wsgi.run_once': False,
'wsgi.url_scheme': 'https',
'wsgi.version': (1, 0)}

No obecně bych k plnému /tmp/ přistupoval tak, že nejprve zjistím co je tam tak velkého a napíšu to sem, snad du -sc /tmp/* | sort -n | tail dá dost informací. (To jde zkusit i dříve než se zaplní.) Pak se to dá předat někomu kdo dobře zná tu komponentu co zaplnění způsobuje.

Nakonec to vypada na minidlna:
root@turris:~# du -sc /tmp/* | sort -n | tail
du: can’t open ‘/tmp/run/mountd/sda1’: Symbolic link loop
8 /tmp/kresd
8 /tmp/state
8 /tmp/sysinfo
12 /tmp/user_notify
16 /tmp/syslog-ng.persist
52 /tmp/log
124 /tmp/luci-modulecache
160 /tmp/lib
1034256 /tmp/run
1034720 total
root@turris:~# du -sc /tmp/run/* | sort -n | tail
du: can’t open ‘/tmp/run/mountd/sda1’: Symbolic link loop
4 /tmp/run/resolver.name
4 /tmp/run/resolver.pid
4 /tmp/run/sfpswitch.lock
4 /tmp/run/sshd.pid
4 /tmp/run/suricata
4 /tmp/run/udhcpc-eth1.pid
4 /tmp/run/wifi-phy0.pid
4 /tmp/run/wifi-phy1.pid
1034164 /tmp/run/minidlna
1034256 total
root@turris:~# du -sc /tmp/run/minidlna | sort -n | tail
1034164 /tmp/run/minidlna
1034164 total
root@turris:~# du -sc /tmp/run/minidlna/* | sort -n | tail
4 /tmp/run/minidlna/minidlna.pid
328 /tmp/run/minidlna/art_cache
1033832 /tmp/run/minidlna/files.db
1034164 total
Po deaktivaci to vypada, ze se prestalo /tmp plnit.

2 Likes