panic: runtime error: index out of range

[plessbd]

./dw-query-digest-amd64 -debug /data/database/db-slow.log
INFO[0000] using "/data/database/db-slow.log" as input file
INFO[0000] using "terminal" output
ERRO[0000] cachefile /data/database/db-slow.log not found: stat /data/database/db-slow.log.cache: no such file or directory
INFO[0000] file has 5933 lines
ERRO[0000] error reading log header: unable to parse server information; beginning of log might be missing
DEBU[0000] line (7) will fold after SELECT
DEBU[0000] line (8) will fold after
DEBU[0000] line (9) will fold after
DEBU[0000] line (10) will fold after
DEBU[0000] line (11) will fold after
DEBU[0000] line (12) will fold after
DEBU[0000] worker exiting
panic: runtime error: index out of range

goroutine 6 [running]:
main.fileReader(0xc000019cf0, 0x5aa9a0, 0xc00000e0a0, 0xc0000569c0, 0x172d)
	/home/leucos/dev/perso/projects/dw-query-digest/main.go:456 +0xaa0
created by main.main
	/home/leucos/dev/perso/projects/dw-query-digest/main.go:303 +0xafa

[root@db ~]# head -n15 /data/database/db-slow.log
/usr/libexec/mysqld, Version: 5.5.60-MariaDB (MariaDB Server). started with:
Tcp port: 3306  Unix socket: /var/lib/mysql/mysql.sock
Time                 Id Command    Argument
# Time: 190603 23:14:02
# User@Host: user[user] @  [172.22.0.10]
# Thread_id: 3  Schema: thedb  QC_hit: No
# Query_time: 0.167214  Lock_time: 0.166911  Rows_sent: 1  Rows_examined: 69
use thedb;
SET timestamp=1559618042;
SELECT
                id, password
            FROM
                Users
            WHERE
                username = 'olntwrdorwvtor'
                AND user_type != '14';
# User@Host: user[user] @  [172.22.0.10]

[leucos]

Thanks for the bug report @plessbd .

I can reproduce the header parsing problem using your log file, but not the crash. Are you using v0.8 ?

/usr/libexec/mysqld, Version: 5.5.60-MariaDB (MariaDB Server). started with:
Tcp port: 3306  Unix socket: /var/lib/mysql/mysql.sock
Time                 Id Command    Argument
# Time: 190603 23:14:02
# User@Host: user[user] @  [172.22.0.10]
# Thread_id: 3  Schema: thedb  QC_hit: No
# Query_time: 0.167214  Lock_time: 0.166911  Rows_sent: 1  Rows_examined: 69
use thedb;
SET timestamp=1559618042;
SELECT
                id, password
            FROM
                Users
            WHERE
                username = 'olntwrdorwvtor'
                AND user_type != '14';
# User@Host: user[user] @  [172.22.0.10]
$ md5sum issue.log
144906c84b46036d3744096dbb88c7af  issue.log

[leucos]

@plessbd I've pushed a fix on master that should take care of MariaDB server version parsing. Can you build master and try again ? If it is a burden, don't hesitate asking and I'll release a binary.

Thanks !

[plessbd]

The ERRO[0000] error reading log header: unable to parse server information; beginning of log might be missing is resolved

so that was a truncated log and I assumed the issue was with lines 7 - 12 of the querylog.

Could it be in a different query that the error is happening?

root@220e9245c0cc:/go/dw-query-digest# md5sum /scratch/scratch/issue.log
9709cc10feee84459188e9ef869c84c7  /scratch/scratch/issue.log
root@220e9245c0cc:/go/dw-query-digest# cat /scratch/scratch/issue.log
/usr/libexec/mysqld, Version: 5.5.60-MariaDB (MariaDB Server). started with:
Tcp port: 3306  Unix socket: /var/lib/mysql/mysql.sock
Time                 Id Command    Argument
# Time: 190603 23:14:02
# User@Host: user[user] @  [172.22.0.10]
# Thread_id: 3  Schema: thedb  QC_hit: No
# Query_time: 0.167214  Lock_time: 0.166911  Rows_sent: 1  Rows_examined: 69
use thedb;
SET timestamp=1559618042;
SELECT
                id, password
            FROM
                Users
            WHERE
                username = 'olntwrdorwvtor'
                AND user_type != '14';
# User@Host: user[user] @  [172.22.0.10]
# Thread_id: 3  Schema: thedb  QC_hit: No
# Query_time: 0.000089  Lock_time: 0.000020  Rows_sent: 0  Rows_examined: 69
SET timestamp=1559618042;
SELECT id FROM Users WHERE username=NULL;

[leucos]

@plessbd I reproduced:

9709cc10feee84459188e9ef869c84c7  issue.log
$ ./bin/dw-query-digest --nocache --debug issue.log
INFO[0000] using "issue.log" as input file              
INFO[0000] using "terminal" output                      
INFO[0000] file has 21 lines                            
INFO[0000] aggregator started                           
DEBU[0000] line (7) will fold after SELECT              
DEBU[0000] line (8) will fold after                     
DEBU[0000] line (9) will fold after                     
DEBU[0000] line (10) will fold after                    
DEBU[0000] line (11) will fold after                    
DEBU[0000] line (12) will fold after                    
DEBU[0000] worker exiting                               
panic: runtime error: index out of range

goroutine 6 [running]:
main.fileReader(0xc00001ddb0, 0x5abce0, 0xc0000100a0, 0xc0000a48a0, 0x15)
	/home/leucos/dev/perso/projects/dw-query-digest/main.go:456 +0xaa0
created by main.main
	/home/leucos/dev/perso/projects/dw-query-digest/main.go:303 +0xafa

I'll look into it. Thanks !

[leucos]

Hey @plessbd . It should be fixed now. If you can give it a try, I'll release afterwards. Thanks !

[plessbd]

It seems to work. However I do get A LOT of warnings about WARN[0027] request to add element 8 for line "some sql" exceeds capacity for what seems like every line it seems your change on https://github.com/devops-works/dw-query-digest/blob/54196e2b2b28bdc3b147d9a9f8982a99d7a3b9cf/main.go#L439 of adding the -1 is causing the issue