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


#1

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?


#2

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


#3

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šší.


#4

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…


#5

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.


#6

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.


#7

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


#8

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.


#9

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?


#10

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.


#11

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.


#12

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.)


#13

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).


#14

Ano pruvodnim jevem je plne /tmp.
Michal Smolak


#15

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)}


#16

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.


#17

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.