[Gluster-users] Geo-Replication - UnicodeEncodeError: 'utf-8' codec can't encode character '\udcfc' in position 78: surrogates not allowed
Dietmar Putz
dietmar.putz at 3q.video
Fri Feb 26 13:16:37 UTC 2021
Hi Andreas,
recently i have been faced with the same fault. I'm pretty sure you are
speaking german, that's why a translation should not be necessary.
I found the reason by tracing a certain process which points to the
gsyncd.log and looking backward from the error until i found some
lgetxattr function call's. In the corresponding directory i found some
filenames with 'special' characters. Rename fixed the problem.
Below 'my' history and solution for UnicodeEncodeError und
UnicodeDecodeError. Hope it helps...btw, we are running gfs 7.9 on
Ubuntu 18.04.
best regards
Dietmar
script fuer trace von geo-replication :
[ 07:35:09 ] - root at gl-master-05 ~/tmp/geo-rep $cat trace_gf.sh
#!/bin/bash
#
# script zum tracen der geo-rep aktivitaeten
# script benoetigt pid
# gedacht zum tracen der parent pid von master prozess auf gsyncd.log
# in diesem beispiel pid 13620
#
#
#[ 16:19:24 ] - root at gl-master-05
/var/log/glusterfs/geo-replication/mvol1_gl-slave-01-int_svol1 $lsof
gsyncd.log
#COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
#python3 13021 root 3w REG 8,2 2905607 9572924 gsyncd.log
#python3 13619 root 3w REG 8,2 2905607 9572924 gsyncd.log
#python3 13620 root 3w REG 8,2 2905607 9572924 gsyncd.log
#[ 16:19:27 ] - root at gl-master-05
/var/log/glusterfs/geo-replication/mvol1_gl-slave-01-int_svol1 $
#
#gf_log="/var/log/glusterfs/geo-replication/mvol1_gl-slave-01-int_svol1/gsyncd.log"
tr_out="/root/tmp/geo-rep/trace-`date +"%H_%M_%S_%d_%m_%Y"`.out"
echo "tr_out : $tr_out"
#pid=`lsof "$gf_log" | grep -v COMMAND | head -1 | awk '{print $2}'`
PID=$1
echo "pid : $PID"
ps -p $PID > /dev/null 2>&1
if [ $? -ne 0 ]
then
echo "Pid $PID not running"
exit
fi
nohup strace -t -f -s 256 -o $tr_out -p$PID &
PID_STRACE=`ps -aef | grep -v grep | grep strace | awk '{print $2}'`
echo "Pid von strace : $PID_STRACE"
while true
do
filesize=`ls -l $tr_out | awk '{print $5}'`
if [ $filesize -gt 1000000000 ]
then
ps -p $PID > /dev/null 2>&1
if [ $? -eq 0 ]
then
kill -9 $PID_STRACE
sleep 1
rm $tr_out
nohup strace -t -f -s 256 -o $tr_out -p$PID &
PID_STRACE=`ps -aef | grep -v grep | grep strace | awk
'{print $2}'`
echo "Pid von strace : $PID_STRACE"
else
echo "pid $PID laeuft nicht mehr...."
exit
fi
fi
ps -p $PID > /dev/null 2>&1
if [ $? -ne 0 ]
then
echo "pid $PID laeuft nicht mehr..."
exit
fi
sleep 120
echo "`date` : `ls -lh $tr_out`"
done
----------------------------------------------------------------------------------------------------------------------------------------------------------------------
zu 2. Loesungsansatz (s.u.) :
Fuer diesen Fehler reicht es den 'letzten' Prozess zu tracen. Hier 1236,
nicht 13021. 13021 ist der 'mother' prozess, nach error werden die beien
anderen gekillt und mit neuer pid gestartet, resultat von beobachtungen :
[ 13:00:04 ] - root at gl-master-05 ~/tmp/geo-rep/15 $lsof
/var/log/glusterfs/geo-replication/mvol1_gl-slave-01-int_svol1/gsyncd.log
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
python3 1235 root 3w REG 8,2 2857996 9572924
/var/log/glusterfs/geo-replication/mvol1_gl-slave-01-int_svol1/gsyncd.log
python3 1236 root 3w REG 8,2 2857996 9572924
/var/log/glusterfs/geo-replication/mvol1_gl-slave-01-int_svol1/gsyncd.log
python3 13021 root 3w REG 8,2 2857996 9572924
/var/log/glusterfs/geo-replication/mvol1_gl-slave-01-int_svol1/gsyncd.log
[ 13:00:18 ] - root at gl-master-05 ~/tmp/geo-rep/15 $
[ 13:00:10 ] - root at gl-master-05 ~/tmp/geo-rep $strace -t -f -s 256 -o
/root/tmp/geo-rep/gsyncd1.out -p1236
Um das file nicht zu gross werden zu lassen kann man den strace immer
wieder killen, file loeschen, und strace neu starten. Pech natuerlich
wenn gerade dann der Fehler auftritt. Das file hat schnell eine Groesse
von 1GB und mehr (ca. 10 Minuten, je nach aktivitaet) und viele
Millionen lines...
geo-replication log beobachten, kill von o.g. pid ist allerdings nicht
noetig. Der Prozess endet bei error, und damit auch der trace.
[ 12:32:04 ] - root at gl-master-05
/var/log/glusterfs/geo-replication/mvol1_gl-slave-01-int_svol1 $tail -f
gsyncd.log
...
[2021-02-11 12:53:59.530649] I [master(worker
/brick1/mvol1):1441:process] _GMaster: Batch Completed mode=xsync
duration=178.4717 changelog_start=1613041474
changelog_end=1613041474 num_changelogs=1 stime=None entry_stime=None
[2021-02-11 12:53:59.639853] I [master(worker /brick1/mvol1):1681:crawl]
_GMaster: processing xsync changelog
path=/var/lib/misc/gluster/gsyncd/mvol1_gl-slave-01-int_svol1/brick1-mvol1/xsync/XSYNC-CHANGELOG.1613041477
###################################
[2021-02-11 13:00:57.149347] E [syncdutils(worker
/brick1/mvol1):339:log_raise_exception] <top>: FAIL:
Traceback (most recent call last):
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/syncdutils.py",
line 369, in twrap
tf(*aargs)
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py", line
1666, in Xsyncer
self.Xcrawl()
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py", line
1839, in Xcrawl
self.Xcrawl(e, xtr_root)
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py", line
1839, in Xcrawl
self.Xcrawl(e, xtr_root)
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py", line
1839, in Xcrawl
self.Xcrawl(e, xtr_root)
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py", line
1801, in Xcrawl
xte = self.xtime(e)
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py", line
403, in xtime
return self.xtime_low(rsc, path, **opts)
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py", line
170, in xtime_low
xt = rsc.server.xtime(path, self.uuid)
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/resource.py",
line 104, in ff
return f(*args)
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/resource.py",
line 240, in xtime
8)
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/libcxattr.py",
line 59, in lgetxattr
return gr_query_xattr(cls, path, siz, 'lgetxattr', attr)
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/py2py3.py", line
46, in gr_query_xattr
return cls._query_xattr(path.encode(), size, syscall,
UnicodeEncodeError: 'utf-8' codec can't encode character '\udcfc' in
position 56: surrogates not allowed
[2021-02-11 13:00:57.246779] I [repce(agent
/brick1/mvol1):96:service_loop] RepceServer: terminating on reaching EOF.
[2021-02-11 13:00:57.251649] I
[gsyncdstatus(monitor):248:set_worker_status] GeorepStatus: Worker
Status Change status=Faulty
Um die Suche etwas einfacher zu gestalten ggf. den output auf die letzte
oder die letzten beiden Sekunden reduzieren :
[ 13:32:46 ] - root at gl-master-05 ~/tmp/geo-rep/15 $cat gsyncd1236.out |
grep 13:00:57 > error_sec.out
Der Error String taucht in Zeile 3574 auf :
[ 13:42:21 ] - root at gl-master-05 ~/tmp/geo-rep/15 $grep -n
UnicodeEncode error_sec.out
3574:1298 13:00:57 write(2, "failed with UnicodeEncodeError.\n", 32) = 32
[ 13:42:34 ] - root at gl-master-05 ~/tmp/geo-rep/15 $
genauer aber ist die Suche nach dem ersten string in der Fehlermeldung,
hier in Zeile 3167 :
[ 13:45:55 ] - root at gl-master-05 ~/tmp/geo-rep/15 $grep -n FAIL
error_sec.out
3167:1298 13:00:57 write(3, "[2021-02-11 13:00:57.149347] E
[syncdutils(worker /brick1/mvol1):339:log_raise_exception] <top>: FAIL:
\nTraceback (most recent call last):\n File
\"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/syncdutils.py\",
line 369, in twrap\n tf(*aargs)\n Fil"..., 1772) = 1772
[ 13:47:17 ] - root at gl-master-05 ~/tmp/geo-rep/15 $
Interessant sind die lgetxattr aufrufe unmittelbar vor Auftreten des
ersten strings in der Fehlermeldung, dort Such nach den letzten 'echten'
Pfaden :
[ 13:50:48 ] - root at gl-master-05 ~/tmp/geo-rep/15 $head -3167
error_sec.out | grep lgetxattr | tail -100
...
Oder geich so :
[ 13:50:40 ] - root at gl-master-05 ~/tmp/geo-rep/15 $cat error_sec.out |
grep 'lgetxattr("/brick1/mvol1/' | tail -5
1298 13:00:57
lgetxattr("/brick1/mvol1/./2538/uploads/2015/SA_150316_Aspirin_0,5_Tabletten_Shop.mov",
"trusted.gfid", "\n\271\0030\276\265C~\204^\307\354ZH?\325", 16) = 16
1298 13:00:57
lgetxattr("/brick1/mvol1/./2538/uploads/2015/SA_150316_ASS+C_Ratiopharm_gegen_Schmerzen_Shop.mov",
"trusted.glusterfs.2f5de6e4-66de-40a7-9f24-4762aad3ca96.xtime",
"_\355\16T\0\2%\232", 8) = 8
1298 13:00:57
lgetxattr("/brick1/mvol1/./2538/uploads/2015/SA_150316_ASS+C_Ratiopharm_gegen_Schmerzen_Shop.mov",
"trusted.gfid", "K5\321\3\0\230L\230\262\223\356\227\210N5'", 16) = 16
1298 13:00:57
lgetxattr("/brick1/mvol1/./2538/uploads/2015/SA_150316_Gittalun_Trinktabletten_Europa.mov",
"trusted.glusterfs.2f5de6e4-66de-40a7-9f24-4762aad3ca96.xtime",
"_\355\16T\0\4S,", 8) = 8
1298 13:00:57
lgetxattr("/brick1/mvol1/./2538/uploads/2015/SA_150316_Gittalun_Trinktabletten_Europa.mov",
"trusted.gfid" <unfinished ...>
[ 13:50:48 ] - root at gl-master-05 ~/tmp/geo-rep/15 $
Eine Suche im entsprechenden Directory zeigt das 'ueble' File :
[ 13:54:12 ] - root at gl-master-05 ~/tmp/geo-rep/15 $ls
/brick1/mvol1/2538/uploads/2015/ | perl -ne 'print "$. $_" if
m/[\x80-\xFF]/'
170 SA_150316_Nasenspray_f�r_Erwachsene_Europa.mov
[ 13:54:57 ] - root at gl-master-05 ~/tmp/geo-rep/15 $
Jetzt wird auch die Zaehlweise klar, annahme erstes character hat index
0 ...can't encode character '\udcfc' in position 56.
/brick1/mvol1/./2538/uploads/2015/SA_150316_Nasenspray_f�r_Erwachsene_Europa.mov
Im gluster ist noch ein file mit diesem character, allerdings nicht auf
gl-master-05/06 :
[ 13:54:57 ] - root at gl-master-05 ~/tmp/geo-rep/15 $ls
/sdn/2538/uploads/2015/ | perl -ne 'print "$. $_" if m/[\x80-\xFF]/'
476 SA_150316_Nasenspray_f�r_Erwachsene_Europa.mov
477 SA_150316_Nasenspray_f�r_Erwachsene_Shop.mov
[ 14:00:10 ] - root at gl-master-05 ~/tmp/geo-rep/15 $
Eine andere Sicht :
[ 14:02:01 ] - root at gl-master-05 ~/tmp/geo-rep/15 $ls -l
/sdn/2538/uploads/2015/SA_150316_Nasenspray_f*
-rw-r--r-- 1 2001 2001 91133255 May 21 2015
'/sdn/2538/uploads/2015/SA_150316_Nasenspray_f'$'\374''r_Erwachsene_Europa.mov'
-rw-r--r-- 1 2001 2001 86655912 May 21 2015
'/sdn/2538/uploads/2015/SA_150316_Nasenspray_f'$'\374''r_Erwachsene_Shop.mov'
-rw-r--r-- 1 2001 2001 91133255 May 21 2015
/sdn/2538/uploads/2015/SA_150316_Nasenspray_fuer_Erwachsene_Europa.mov
-rw-r--r-- 1 2001 2001 86655912 May 21 2015
/sdn/2538/uploads/2015/SA_150316_Nasenspray_fuer_Erwachsene_Shop.mov
[ 14:02:45 ] - root at gl-master-05 ~/tmp/geo-rep/15 $
die ersten beiden Files werden geloescht.
[ 14:22:32 ] - root at gl-master-05 /sdn/2538/uploads/2015 $rm
'SA_150316_Nasenspray_f'$'\374''r_Erwachsene_Europa.mov'
[ 14:22:43 ] - root at gl-master-05 /sdn/2538/uploads/2015 $rm
'SA_150316_Nasenspray_f'$'\374''r_Erwachsene_Shop.mov'
[ 14:23:11 ] - root at gl-master-05 ~/tmp/geo-rep/15 $ls
/brick1/mvol1/2538/uploads/2015/ | perl -ne 'print "$. $_" if
m/[\x80-\xFF]/'
[ 14:23:55 ] - root at gl-master-05 ~/tmp/geo-rep/15 $
[ 14:23:55 ] - root at gl-master-05 ~/tmp/geo-rep/15 $ls
/sdn/2538/uploads/2015/ | perl -ne 'print "$. $_" if m/[\x80-\xFF]/'
[ 14:24:35 ] - root at gl-master-05 ~/tmp/geo-rep/15 $
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
2 Neue Phaenomene, beide aeussern sich mit der gleichen Meldung in
/var/log/glusterfs/geo-replication/mvol1_gl-slave-01-int_svol1 :
[2021-02-09 09:39:03.984410] I [master(worker /brick1/mvol1):1681:crawl]
_GMaster: processing xsync changelog
path=/var/lib/misc/gluster/gsyncd/mvol1_gl-slave-01-int_svol1/brick1-mvol1/xsync/XSYNC-CHANGELOG.1612862967
[2021-02-09 09:39:46.321001] E [syncdutils(worker
/brick1/mvol1):339:log_raise_exception] <top>: FAIL:
Traceback (most recent call last):
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/syncdutils.py",
line 369, in twrap
tf(*aargs)
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py", line
1666, in Xsyncer
self.Xcrawl()
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py", line
1839, in Xcrawl
self.Xcrawl(e, xtr_root)
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py", line
1839, in Xcrawl
self.Xcrawl(e, xtr_root)
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py", line
1839, in Xcrawl
self.Xcrawl(e, xtr_root)
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py", line
1801, in Xcrawl
xte = self.xtime(e)
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py", line
403, in xtime
return self.xtime_low(rsc, path, **opts)
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py", line
170, in xtime_low
xt = rsc.server.xtime(path, self.uuid)
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/resource.py",
line 104, in ff
return f(*args)
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/resource.py",
line 240, in xtime
8)
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/libcxattr.py",
line 59, in lgetxattr
return gr_query_xattr(cls, path, siz, 'lgetxattr', attr)
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/py2py3.py", line
46, in gr_query_xattr
return cls._query_xattr(path.encode(), size, syscall,
UnicodeEncodeError: 'utf-8' codec can't encode character '\udcfc' in
position 38: surrogates not allowed
[2021-02-09 09:39:46.601226] I [repce(agent
/brick1/mvol1):96:service_loop] RepceServer: terminating on reaching EOF.
[2021-02-09 09:39:46.607766] I
[gsyncdstatus(monitor):248:set_worker_status] GeorepStatus: Worker
Status Change status=Faulty
2 Unterschiedliche Loesungen. Allgemeines :
In
/var/lib/misc/gluster/gsyncd/mvol1_gl_slave-01-int_svol1/brick1-mvol1/xsync/
werden die aktuell verarbeiteten XSYNC-CHANGELOG files kopiert und
abgearbeitet. ist ein file abgearbeitet wird es in ~/archieve.tar
verschoben und das naechste file ist dran. Das aber nur solange der
Knoten im hybrid-crawl ist (wie es mit den neuen Servern gl-master-05,
-06 der Fall ist nachdem sie mit add-brick geadded wurden). Laeuft die
geo-rep in dieser Phase auf einen Fehler, dann wird das genannte
directory geleert (ausser archive.tar) und fuer den naechsten lauf
wieder langsam gefuellt...bis changelog-crawl erreicht ist (dann
/brick1/mvol1/.glusterfs/changelogs/CHANGELOG*).
Insofern sollte man unbedingt ein tail -f
/var/log/glusterfs/.../.../gsyncd.log auf haben, um den Zeitpunkt des
Fehlers nicht zu verpassen. ggf. die log-files temporaer sichern.
1. Setzt wohl etwas Glueck voraus :
cd
/var/lib/misc/gluster/gsyncd/mvol1_gl-slave-01-int_svol1/brick1-mvol1/xsync/
file XSYNC-CHANGELOG.*
Ein file war dabei vom Type UTF-8 Unicode text, alle anderen sind ASCII
tesxt.
[ 11:35:23 ] - root at gl-master-05 ~/tmp/geo-rep/1 $file
XSYNC-CHANGELOG.1612792550XSYNC-CHANGELOG.
XSYNC-CHANGELOG.1612792550: UTF-8 Unicode text
[ 11:36:12 ] - root at gl-master-05 ~/tmp/geo-rep/1 $
[ 11:34:23 ] - root at gl-master-05 ~/tmp/geo-rep/1 $perl -ne 'print "$.
$_" if m/[\x80-\xFF]/' XSYNC-CHANGELOG.1612792550
4983 E 90778e6b-bd99-4580-9c73-a341281e0aa1 MKNOD 33188 0 0
c2e46ace-2720-424d-93df-d777f6e7de26/005_Ron_AshtangaYogaFuerAnfänger_1209_music_full.mp4
[ 11:35:23 ] - root at gl-master-05 ~/tmp/geo-rep/1 $
Das file hat ein 'ä' im Namen, das war der show-stopper, umbenennen und
es ging weiter.
Finden des Files gestaltet sich etwas schwierig, hier aus anderem Fehler
der geo-rep :
[ 14:46:15 ] - root at gl-master-05 ~/tmp/geo-rep/12 $perl -ne 'print "$.
$_" if m/[\x80-\xFF]/' XSYNC-CHANGELOG.1612880447
4665 E e0eaeee6-004a-44df-8666-6504a12d6374 MKNOD 33188 0 0
15fc6b30-bc2d-4f77-bdb6-ce7e52797e15/M0301_SHLV_DS_Volumenberechnung-von-Rotationskörpern-um-die-y-Achse.mp4
[ 14:46:46 ] - root at gl-master-05 ~/tmp/geo-rep/12 $
mysql> select Name,StreamFK from Files where Name like
'%M0301_SHLV_DS_Volumenberechnung-von-Rotations%';
+----------------------------------------------------------------------------------+----------+
| Name | StreamFK |
+----------------------------------------------------------------------------------+----------+
|
uploads/M0301_SHLV_DS_Volumenberechnung-von-Rotationskörpern-um-die-y-Achse.mp4
| 2491 |
+----------------------------------------------------------------------------------+----------+
1 row in set (1.68 sec)
mysql>
StreamFK ist der Ordner in /sdn/
2. erheblich aufwendiger :
der Ansatz aus 1. bringt hier nichts, alle XSYNC-CHANGELOG files sind
vom type Ascii, das Komanndo perl -ne 'print "$. $_" if m/[\x80-\xFF]/'
XSYNC-CHANGELOG.* foerdert nichts zu tage.
Hier wieder den Prozess tracen der auf gsyncd.log zeigt :
[ 11:54:05 ] - root at gl-master-05
/var/log/glusterfs/geo-replication/mvol1_gl-slave-01-int_svol1 $lsof
gsyncd.log
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
python3 13021 root 3w REG 8,2 2530858 9572924 gsyncd.log
python3 32182 root 3w REG 8,2 2530858 9572924 gsyncd.log
python3 32183 root 3w REG 8,2 2530858 9572924 gsyncd.log
[ 11:54:09 ] - root at gl-master-05
/var/log/glusterfs/geo-replication/mvol1_gl-slave-01-int_svol1 $
Der Fehlerintervall lag bei etwa 5 1/2 Minuten, manchmal 10 Minuten. Der
trace wird u.U. ziemlich gross. Wichtig dabei ist, den Trace auf die
parent pid moeglichst kurz vor error zu starten und dann einen ganzen
Intervall abzuwarten bevor der trace gestoppt wird.
Es ist wahrscheinlich auch ausreichend, einen der beiden angezeigten
follow-prozesse zu tracen, wobei wahrscheinlich ein start des trace kurz
vor Auftritt des Fehlers reicht, abbruch direkt nach error. Muss man
halt testen, ein kurzer Blick weist darauf hin den 'geschwaetzigeren'
der beiden zu tracen.
[ 12:02:07 ] - root at gl-master-05 ~ $strace -t -f -s 256 -o
/root/tmp/geo-rep/gsyncd1.out -p13021
However, ein paar Eckdaten :
[ 10:59:27 ] - root at gl-master-05 ~/tmp/geo-rep/11 $ls -lh gsyncd1.out
-rw-r--r-- 1 root root 2.1G Feb 9 09:40 gsyncd1.out
[ 12:04:29 ] - root at gl-master-05 ~/tmp/geo-rep/11 $cat gsyncd1.out | wc -l
15354607
[ 12:04:37 ] - root at gl-master-05 ~/tmp/geo-rep/11 $
Der Error-String ist im trace output sichtbar :
[ 12:05:52 ] - root at gl-master-05 ~/tmp/geo-rep/11 $grep
UnicodeEncodeError gsyncd1.out
32183 09:39:46 write(2, "failed with UnicodeEncodeError.\n", 32) = 32
[ 12:06:14 ] - root at gl-master-05 ~/tmp/geo-rep/11 $
Am besten man naehert sich dem vermuteten Ereignis vom Fehlerzeitpunkt
rueckwaerts und schaut sich die letzten lgetxattr calls vor Fehler an.
In diesem Fall wird gerade der Pfad /brick1/mvol1/2491/uploads/portale
abgearbeitet, dann kein lgetxattr mehr bis zum Fehler :
[ 12:08:42 ] - root at gl-master-05 ~/tmp/geo-rep/11 $grep 09:39:46
gsyncd1.out | grep lgetxattr | tail -10
32183 09:39:46
lgetxattr("/brick1/mvol1/./2491/uploads/portale/Starthilfe_Login_ICAS7.mp4",
"trusted.gfid", "\234\352\274\301\v\220O\223\225\r7H\325p\5\231", 16) = 16
32183 09:39:46
lgetxattr("/brick1/mvol1/./2491/uploads/portale/Terminhistorie.mp4",
"trusted.glusterfs.2f5de6e4-66de-40a7-9f24-4762aad3ca96.xtime",
"_\354\255\304\0\3&\370", 8) = 8
32183 09:39:46
lgetxattr("/brick1/mvol1/./2491/uploads/portale/Terminhistorie.mp4",
"trusted.gfid", "\20dI\7f$M0\253\244\306\20\201\23T\3", 16) = 16
32183 09:39:46
lgetxattr("/brick1/mvol1/./2491/uploads/portale/Begruessungsanruf.mp4",
"trusted.glusterfs.2f5de6e4-66de-40a7-9f24-4762aad3ca96.xtime",
"_\354\255\304\0\n\377\252", 8) = 8
32183 09:39:46
lgetxattr("/brick1/mvol1/./2491/uploads/portale/Begruessungsanruf.mp4",
"trusted.gfid", "U;;\254\6RJC\270:\302\t\317ZJ\"", 16) = 16
32183 09:39:46
lgetxattr("/brick1/mvol1/./2491/uploads/portale/Part_2.mp4",
"trusted.glusterfs.2f5de6e4-66de-40a7-9f24-4762aad3ca96.xtime",
"_\354\255\305\0\4\265\2", 8) = 8
32183 09:39:46
lgetxattr("/brick1/mvol1/./2491/uploads/portale/Part_2.mp4",
"trusted.gfid", "\266\r\226\16\224vE>\232\255k\250\205z\3411", 16) = 16
32183 09:39:46
lgetxattr("/brick1/mvol1/./2491/uploads/portale/Part_3.mp4",
"trusted.glusterfs.2f5de6e4-66de-40a7-9f24-4762aad3ca96.xtime",
"_\354\255\305\0\4\271\24", 8) = 8
32183 09:39:46
lgetxattr("/brick1/mvol1/./2491/uploads/portale/Part_3.mp4",
"trusted.gfid", "\244D\204\364\347lAK\237\265\1:\225Q^y", 16) = 16
32183 09:39:46 read(9, " ex = sys.exc_info()[1]\n if
ex.errno in (ENOENT, ENODATA):\n return False\n
else:\n raise\n\n @classmethod\n @_pathguard\n def
gfid(cls, path):\n buf = errno_wrap(Xattr.lgetxattr, [path,
cls.GF"..., 8192) = 8192
[ 12:16:11 ] - root at gl-master-05 ~/tmp/geo-rep/11 $
[ 10:55:53 ] - root at gl-master-05 ~/tmp/geo-rep/11 $ls
/sdn/2491/uploads/portale/
Film_Tagung.avi 'M'$'\374''ller_M_Wild_Card_II.mp4' Schambach_Tipp.wmv
Vorstellung_Online_Lerncenter_Carlsson.mp4
Anwesenheits-_und_Honorarkorrektur.mp4 Glugovsky_bestes_Gespann.mp4
'M'$'\374''ller_M_Wild_Card.mp4' ...
Da sind die scheiss files. soll wohl Müller heissen. backup, rename,
delete. Geo Rep geht weiter.
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Hi,
neuer geo-rep error und leitfaden zur loesung des problems... fuers
archiv, kann immer mal wieder auftreten. Ursache ist ein Soderzeichen in
einem Filename das ueber proftpd reinkam.
gr. d.
geo-rep error : "UnicodeDecodeError: 'utf-8' codec can't decode byte
0xef in position 140: invalid continuation byte"
erster Fehler auf gl-master-02 umd 20:47:38, Ursache offenbar in
/brick1/mvol1 von gl-master-01,-02 :
/var/log/glusterfs/geo-replication/mvol1_gl-slave-01-int_svol1/gsynd.log
auf gl-master-02:
[2020-12-23 20:47:38.740712] E [syncdutils(worker
/brick1/mvol1):339:log_raise_exception] <top>: FAIL:
Traceback (most recent call last):
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/gsyncd.py", line
332, in main
func(args)
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/subcmds.py", line
86, in subcmd_worker
local.service_loop(remote)
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/resource.py",
line 1315, in service_loop
g2.crawlwrap()
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py", line
602, in crawlwrap
self.crawl()
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py", line
1518, in crawl
self.changelogs_batch_process(changes)
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py", line
1492, in changelogs_batch_process
self.process(batch)
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py", line
1327, in process
self.process_change(change, done, retry)
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py", line
1018, in process_change
clist = f.readlines()
File "/usr/lib/python3.6/codecs.py", line 321, in decode
(result, consumed) = self._buffer_decode(data, self.errors, final)
UnicodeDecodeError: 'utf-8' codec can't decode byte 0xef in position
140: invalid continuation byte
[2020-12-23 20:47:39.687652] I [repce(agent
/brick1/mvol1):96:service_loop] RepceServer: terminating on reaching EOF.
[2020-12-23 20:47:39.818266] I
[gsyncdstatus(monitor):248:set_worker_status] GeorepStatus: Worker
Status Change status=Faulty
[2020-12-23 20:47:50.229159] I
[gsyncdstatus(monitor):248:set_worker_status] GeorepStatus: Worker
Status Change status=Initializing...
[2020-12-23 20:47:50.237147] I [monitor(monitor):159:monitor] Monitor:
starting gsyncd worker brick=/brick1/mvol1 slave_node=gl-slave-04-int
Fehler wiederholt sich laufend. Trace auf log-file und deren
child-prozesse, parent-pid of all scheint 8654 :
[ 05:32:10 ] - root at gl-master-01
/var/log/glusterfs/geo-replication/mvol1_gl-slave-01-int_svol1 $lsof
gsyncd.log
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
python3 8654 root 3w REG 8,2 7030509 8389931 gsyncd.log
python3 8671 root 3w REG 8,2 7030509 8389931 gsyncd.log
python3 8672 root 3w REG 8,2 7030509 8389931 gsyncd.log
Ein 'tail -f gsyncd.log' aufmachen, strace starten und wenigstens ein
Fehlerintervall abwarten :
[ 05:34:42 ] - root at gl-master-01 ~/tmp/geo-rep $strace -t -f -s 256 -o
/root/tmp/geo-rep/gsyncd2.out -p8654
[ 05:36:15 ] - root at gl-master-01 ~/tmp/geo-rep $vi gsyncd2.out
:se nu
129573 17407 05:13:14 write(2, "failed with UnicodeDecodeError.\n", 32)
= 32
129337 17407 05:13:14 write(3, "[2020-12-24 05:13:14.181362] E
[syncdutils(worker /brick1/mvol1):339:log_raise_exception] <top>: FAIL:
\nTraceback (most recent call last):\n File
\"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/gs yncd.py\",
line 332, in main\n func(args)\n File \"/u"..., 1400) = 1400
Die Error-Meldung wird von child-prozess 17407 erzeugt, sind aber keine
weiteren Hinweise im direkten Umfeld zu sehen
In Zeile 129337 vom strace-output steht der Fehler 'line 332'
Rund 75 Zeilen vorher findet sich ein Hinweis auf eine konkrete Datei,
man beachte den Filename, er enthaelt 'Tcha\357kovski' und koennte
Ursache fuer den decode-error :
129262 17407 05:13:14 read(9, "E 606ceb99-6410-40e3-a6f8-b2148a521239
CREATE 33188 2001 2001
14770ef4-f232-4d05-b572-e0dcb38213eb/5881_extrait_en_Euroarts_A_Swan_Lake_Tcha\357kovski_Alexander_Ekman_TheNorwegianNationalBallet_DanceOfTheLittleSwans_IL_16_9_HD.mp4\nD
606ceb99-6410-40e3-a6f8-b2"..., 8192) = 463
File kam ueber proftpd auf gluster-client-02 rein und enthaelt ein
Sonderzeichen in 'Tcha<i>kovski' :
[ 06:10:46 ] - root at gluster-client-02 /data/logs/proftpd $grep -i
swan_lake_tcha extended.log
80.15.161.141 UNKNOWN vod-medici [23/Dec/2020:12:30:31 +0000] "STOR
/5881_full_en_Euroarts_A_Swan_Lake_Tchaïkovski_-_Alexander_Ekman_-_The_Norwegian_National_Ballet_IL_16_9_HD.mp4"
226 9985342580
80.15.161.141 UNKNOWN vod-medici [23/Dec/2020:12:30:34 +0000] "SIZE
/5881_full_en_Euroarts_A_Swan_Lake_Tchaïkovski_-_Alexander_Ekman_-_The_Norwegian_National_Ballet_IL_16_9_HD.mp4"
213 -
80.15.161.141 UNKNOWN vod-medici [23/Dec/2020:12:30:54 +0000] "RETR
/5881_full_en_Euroarts_A_Swan_Lake_Tchaïkovski_-_Alexander_Ekman_-_The_Norwegian_National_Ballet_IL_16_9_HD.mp4"
426 78840
Binary file extended.log matches
[ 06:11:35 ] - root at gluster-client-02 /data/logs/proftpd $
anders als erwartet ist das file nicht auf /brick1/mvol1, sondern auf
/brick2/mvol1/ :
-rw-r--r-- 2 2001 2001 9985342580 Dec 23 12:30
/brick2/mvol1/9378/uploads/2019/5881_full_en_Euroarts_A_Swan_Lake_Tchaïkovski_-_Alexander_Ekman_-_The_Norwegian_National_Ballet_IL_16_9_HD.mp4
Loeschen des files bringt nichts, es taucht weiterhin im strace auf. Im
trace ist vor dem ersten Auftreten von 'Swan_Lake' eine
CHANGELOG.1608756454 zu sehen. Da sieht man was das Sonderzeichen
anrichtet...Zeilenumbruch an der Stelle des Sonerzeichen.
[ 08:09:47 ] - root at gl-master-01 /brick2/mvol1/.glusterfs/changelogs
$strings /brick1/mvol1/.glusterfs/changelogs/CHANGELOG.1608756454
GlusterFS Changelog | version: v1.2 | encoding : 2
E606ceb99-6410-40e3-a6f8-b2148a521239
33188
2001
2001
14770ef4-f232-4d05-b572-e0dcb38213eb/5881_extrait_en_Euroarts_A_Swan_Lake_Tcha
kovski_Alexander_Ekman_TheNorwegianNationalBallet_DanceOfTheLittleSwans_IL_16_9_HD.mp4
D606ceb99-6410-40e3-a6f8-b2148a521239
E238fe8f1-5469-4886-855e-9c225f04f11b
16877
aea0a0a6-69a5-4c31-bf81-a30ee1fb0f8c/2458246
M1387ea1f-5a24-45a7-ac93-942dba49c455
M238fe8f1-5469-4886-855e-9c225f04f11b
[ 08:10:46 ] - root at gl-master-01 /brick2/mvol1/.glusterfs/changelogs $
[ 08:46:35 ] - root at gl-master-02 ~/tmp/geo-rep $strings
CHANGELOG.1608756455
GlusterFS Changelog | version: v1.2 | encoding : 2
E606ceb99-6410-40e3-a6f8-b2148a521239
33188
2001
2001
14770ef4-f232-4d05-b572-e0dcb38213eb/5881_extrait_en_Euroarts_A_Swan_Lake_Tcha
kovski_Alexander_Ekman_TheNorwegianNationalBallet_DanceOfTheLittleSwans_IL_16_9_HD.mp4
D606ceb99-6410-40e3-a6f8-b2148a521239
E238fe8f1-5469-4886-855e-9c225f04f11b
16877
aea0a0a6-69a5-4c31-bf81-a30ee1fb0f8c/2458246
M1387ea1f-5a24-45a7-ac93-942dba49c455
M238fe8f1-5469-4886-855e-9c225f04f11b
[ 08:46:39 ] - root at gl-master-02 ~/tmp/geo-rep $
Die betreffende changelog-Datei ist die zweite in der chronologischen
Auflistung aller angefassten changelog-dateien im straceoutput, auch
darueber kann man sich annaehern :
[ 08:39:25 ] - root at gl-master-01 ~/tmp/geo-rep $cat gsyncd6.out | grep
CHANGELOG. | grep " stat" | grep "/brick1/mvol1/.glusterfs/" | wc -l
178
[ 08:39:33 ] - root at gl-master-01 ~/tmp/geo-rep $
[ 08:37:06 ] - root at gl-master-01 ~/tmp/geo-rep $cat gsyncd6.out | grep
CHANGELOG. | grep " stat" | grep "/brick1/mvol1/.glusterfs/" | awk
'{print $3}' | cut -f2- -d. | cut -f1 -d\" | sort -n | more
glusterfs/changelogs/CHANGELOG.1608756440
glusterfs/changelogs/CHANGELOG.1608756454###
glusterfs/changelogs/CHANGELOG.1608756468
glusterfs/changelogs/CHANGELOG.1608756483
glusterfs/changelogs/CHANGELOG.1608756498
...
Loesungsansatz, unkonventionell : verschieben der entsprechenden
changelog datei raus aus /brick1/mvol1/.glusterfs/changelogs/ und
checken ob der Fehler uebersprungen wird :
[ 09:19:02 ] - root at gl-master-01 /brick1/mvol1/.glusterfs/changelogs $mv
CHANGELOG.1608756454 ..
Danach faengt sich die geo-rep kurz und laeuft auf aehnlichen Fehler,
diesmal an Posistion 124 :
2020-12-24 09:16:41.303597] E [syncdutils(worker
/brick1/mvol1):339:log_raise_exception] <top>: FAIL:
Traceback (most recent call last):
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/gsyncd.py", line
332, in main
func(args)
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/subcmds.py", line
86, in subcmd_worker
local.service_loop(remote)
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/resource.py",
line 1297, in service_loop
g3.crawlwrap(oneshot=True)
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py", line
602, in crawlwrap
self.crawl()
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py", line
1592, in crawl
self.changelogs_batch_process(changes)
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py", line
1492, in changelogs_batch_process
self.process(batch)
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py", line
1327, in process
self.process_change(change, done, retry)
File
"/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py", line
1018, in process_change
clist = f.readlines()
File "/usr/lib/python3.6/codecs.py", line 321, in decode
(result, consumed) = self._buffer_decode(data, self.errors, final)
UnicodeDecodeError: 'utf-8' codec can't decode byte 0xef in position
124: invalid continuation byte
[2020-12-24 09:16:41.374715] I [repce(agent
/brick1/mvol1):96:service_loop] RepceServer: terminating on reaching EOF.
[2020-12-24 09:16:42.168337] I [monitor(monitor):280:monitor] Monitor:
worker died in startup phase brick=/brick1/mvol1
Danach switched die geo-rep 2-3 mal hin und her und bevor strace
gestartet werden kann scheint sich die geo-rep 'gefangen' zu haben. kein
switch mehr und status history crawl :
[ 09:23:51 ] - root at gl-master-01 /brick1/mvol1/.glusterfs/changelogs
$gluster volume geo-replication mvol1 gl-slave-01-int::svol1 status
MASTER NODE MASTER VOL MASTER BRICK SLAVE USER
SLAVE SLAVE NODE STATUS CRAWL STATUS LAST_SYNCED
--------------------------------------------------------------------------------------------------------------------------------------------------------------
gl-master-01-int mvol1 /brick1/mvol1 root
gl-slave-01-int::svol1 gl-slave-03-int Active History Crawl
2020-12-23 20:47:19
gl-master-01-int mvol1 /brick2/mvol1 root
gl-slave-01-int::svol1 gl-slave-03-int Active Changelog Crawl
2020-12-24 09:24:59
gl-master-04-int mvol1 /brick1/mvol1 root
gl-slave-01-int::svol1 gl-slave-03-int Passive N/A N/A
gl-master-04-int mvol1 /brick2/mvol1 root
gl-slave-01-int::svol1 gl-slave-03-int Passive N/A N/A
gl-master-02-int mvol1 /brick1/mvol1 root
gl-slave-01-int::svol1 gl-slave-04-int Passive N/A N/A
gl-master-02-int mvol1 /brick2/mvol1 root
gl-slave-01-int::svol1 gl-slave-04-int Passive N/A N/A
gl-master-03-int mvol1 /brick1/mvol1 root
gl-slave-01-int::svol1 gl-slave-01-int Active Changelog Crawl
2020-12-24 09:25:18
gl-master-03-int mvol1 /brick2/mvol1 root
gl-slave-01-int::svol1 gl-slave-01-int Active Changelog Crawl
2020-12-24 09:25:14
[ 09:25:26 ] - root at gl-master-01 /brick1/mvol1/.glusterfs/changelogs $
Nach der ganzen Aktion muss die CHANGELOG.1608756454 auf Inhalt
ausgewertet und ueberprueft werden, ob alles geo-repliziert wurde.
Error taucht spaeter wieder auf ...in position 124: ... Recherche nach
gleichem Prinzip bringt wieder den 'Swan_Lake' zum vorschein :
[ 09:39:35 ] - root at gl-master-01 ~/tmp/geo-rep $cat gsyncd7.out | grep
CHANGELOG. | grep " stat" | grep "/brick1/mvol1/.glusterfs/" | awk
'{print $3}' | cut -f2- -d. | cut -f1 -d\" | sort -n | head -5
glusterfs/changelogs/CHANGELOG.1608757775
glusterfs/changelogs/CHANGELOG.1608757789
glusterfs/changelogs/CHANGELOG.1608757803
glusterfs/changelogs/CHANGELOG.1608757817
glusterfs/changelogs/CHANGELOG.1608757831
[ 09:40:18 ] - root at gl-master-01 ~/tmp/geo-rep $strings
CHANGELOG.1608757803
GlusterFS Changelog | version: v1.2 | encoding : 2
E606ceb99-6410-40e3-a6f8-b2148a521239
14770ef4-f232-4d05-b572-e0dcb38213eb/5881_extrait_en_Euroarts_A_Swan_Lake_Tcha
kovski_Alexander_Ekman_TheNorwegianNationalBallet_DanceOfTheLittleSwans_IL_16_9_HD.mp4
[ 09:40:21 ] - root at gl-master-01 ~/tmp/geo-rep $
[ 09:53:40 ] - root at gl-master-01 /brick1/mvol1/.glusterfs/changelogs $mv
CHANGELOG.1608757803 ..
danach gehts erst mal weiter... beobachten.
On 26.02.21 11:35, Andreas Kirbach wrote:
> Hi everyone,
>
> when trying starting a freshly created geo-replication session I do
> get the following error:
> ---
> [2021-02-26 10:12:38.376731] E [syncdutils(worker
> /redacted/brick/path):363:log_raise_exception] <top>: FAIL:
> Traceback (most recent call last):
> File
> "/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/syncdutils.py",
> line 393, in twrap
> tf(*aargs)
> File
> "/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py",
> line 1672, in Xsyncer
> self.Xcrawl()
> File
> "/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py",
> line 1845, in Xcrawl
> self.Xcrawl(e, xtr_root)
> File
> "/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py",
> line 1845, in Xcrawl
> self.Xcrawl(e, xtr_root)
> File
> "/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py",
> line 1845, in Xcrawl
> self.Xcrawl(e, xtr_root)
> File
> "/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py",
> line 1845, in Xcrawl
> self.Xcrawl(e, xtr_root)
> File
> "/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py",
> line 1807, in Xcrawl
> xte = self.xtime(e)
> File
> "/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py",
> line 405, in xtime
> return self.xtime_low(rsc, path, **opts)
> File
> "/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/master.py",
> line 172, in xtime_low
> xt = rsc.server.xtime(path, self.uuid)
> File
> "/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/resource.py",
> line 105, in ff
> return f(*args)
> File
> "/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/resource.py",
> line 241, in xtime
> 8)
> File
> "/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/libcxattr.py",
> line 59, in lgetxattr
> return gr_query_xattr(cls, path, siz, 'lgetxattr', attr)
> File
> "/usr/lib/x86_64-linux-gnu/glusterfs/python/syncdaemon/py2py3.py",
> line 46, in gr_query_xattr
> return cls._query_xattr(path.encode(), size, syscall,
> UnicodeEncodeError: 'utf-8' codec can't encode character '\udcfc' in
> position 78: surrogates not allowed
> [2021-02-26 10:12:38.885995] I [monitor(monitor):228:monitor] Monitor:
> worker died in startup phase [{brick=/redacted/brick/path}]
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.gluster.org/pipermail/gluster-users/attachments/20210226/cc244f6f/attachment.html>
More information about the Gluster-users
mailing list