某数据下载程序,相同版本的代码,在64位系统中运行正常,但在32位系统中概率性出现断言错误。一旦出现,程序无法正常继续,即使重启亦不行。从年前会上领导提出要追到根,跟到底,到年后的今天,经过排查、自测、试点,算是告一段落了。文中没有很难的技术问题,但过程还是值得记录的。本文从后来者角度总结一下解决问题的过程,同时给出相关测试代码。
由于本文没有技术含量,请谨慎按需阅读。
起因
当运维人员把出错的截图发给我时,我回想起1年半前的那个夏天,那天下午,运维人员将同一个错误截图给我,后来回退版本了,再也没出现了。这次,运维人员上报给了领导。会上我也答不出来为什么在32位系统上会报错,而在64位系统中却不行,也回答不了为什么回退版本又可以。下面这个错误,在笔记里躺了很久,现在又要翻出来,一点也没变化:
ath.c:193: _gcry_ath_mutex_lock: Assertion `*lock == ((ath_mutex_t) 0)' failed.
这是某个动态库报的断言错误,不是业务程序直接提示的。虚拟机模拟不出问题,现场机器没有gdb,也无法生成coredump,也没有pstrace,只能靠头脑分析排查了。
排查及解决
动态库定位
报错信息关键信息为ath.c
、_gcry_ath_mutex_lock
、ath_mutex_t
。
经搜索,得到了一些有用的信息。
在libssh2官方网站上,找到一篇关于FIPS兼容性的帖子FIPS Compliance,提问者的错误是用sftp通过libcurl下载文件时产生的。路线和所遇问题几乎一样,出现断言错误的库为libgcrypt
。在stackoverflow
网站上找到这个帖子,帖子回答者提到:
Obviously you are using libgcrypt in there, either directly or through some library (liboauth?). Multithreaded use of gcrypt requires initialization, as documented at gnupg.org/documentation/manuals/gcrypt/Multi_002dThreading.html - either you forgot it, or one of the maintainers of libraries you used did. Check the documentation… –
DevSolar
Dec 13, 2011 at 17:00
The problem was that more than one thread tries to get a http request at the same time. That’s not possible. So I used mutexes to avoid that.
使用libgcrypt
时,在多线程中要初始化,至于初始化什么,怎么初始化,谁初始化,由于涉及libcurl->libssh2->libgcrypt
等库,路径较深,鞭长莫及,代码人一声叹气。
关于ath.c断言语句的跟踪记录
前面定位到了libgcrypt
库,在32位系统上用strings
命令查找出错关键字:
strings /lib/i386-linux-gnu/libgcrypt.so.11.7.0 | grep "*lock =="
*lock == ((ath_mutex_t) 0)
*lock == ((ath_mutex_t) 1)strings /lib/i386-linux-gnu/libgcrypt.so.11.7.0 | grep "_gcry_ath_mutex_lock"
_gcry_ath_mutex_lock
是这个库无疑了。但11.7.0版本找不到ath.c文件。再在64位系统上查:
strings /lib64/libgcrypt.so.11.8.2 | grep "*lock =="
*lock == ((ath_mutex_t) 0)
*lock == ((ath_mutex_t) 1)strings /lib64/libgcrypt.so.11.8.2 | grep "_gcry_ath_mutex_lock"
_gcry_ath_mutex_lockfind /usr/ -name "libgcrypt*"
/usr/lib64/libgcrypt.so.11.8.2
/usr/lib64/libgcrypt.so.11
/usr/share/doc/libgcrypt-1.5.3
从信息中猜测,可能的版本是1.5.3。下载该版本解压,得到ath.c关键语句:
第193行,正是这多天魂牵梦萦想看到的语句。
但是,这只是知道了出错的地方而已,还不知道如何出错。
问题定位
从错误信息上看,和锁有关,进而推断和多线程有关。分析业务代码,的确有多线程下载。起初,跟踪线程内部的curl变量,但没有出现越界使用情况,都在相同内部线程完成了,每次下载,都用curl_easy_init
初始化,最后用curl_easy_cleanup
清理,通过打印跟踪可以确认这一点。
回到业务程序上。既然是多线程下载出错,就将多线程改成单线程,或者加上互斥锁,不让他们同时运行。这份代码比大锤的年龄还大,有一定的历史沉淀,且有较多名称相近的函数,类似于北湖北路,北湖南路,北湖东路等,不好改动。于是加上锁,再测试,没有发现问题。
解决方法
但依然没有找到原因。
访问libcurl官方示例页面,找到多线程例子,但参考价值不大,于是搭建sftp服务器,写了测试程序。经摸索,发现在一线程下载过程的同时另一线程也下载,则必然出错。开始时,下载的文件小,很快下载完毕,下载大文件时问题即刻暴露了。
回查业务代码,在两线程启动时,人工加了10秒的延时,当数据量较多大了,前一线程未下载完毕,后一线程启动,因此报错了。之前相安无事,应该是两线程下载的数据量并非都大,前一线程较快完成了下载。
但无论如何,在两线程之间加锁,的确能解决问题。
反馈
在试点跑了3天,暂时没有收到问题反馈。应该大概的确解决了这个问题。
小结
至于为何libcurl无法多线程下载,为何偏偏在32位系统上出现,其实还没有找到根本问题所在。多方测试,64位系统的确未发现有。于是在业务代码中通过宏定义限定只在32位系统才加锁。
附:自测程序
源码:
#include <stdio.h>
#include <errno.h>
#include <string.h>
#include <unistd.h>
#include <pthread.h>
#include <curl/curl.h>#define DOWNLOAD_LOCKstatic pthread_mutex_t connlock;void init_locks(void)
{pthread_mutex_init(&connlock, NULL);
}void kill_locks(void)
{pthread_mutex_destroy(&connlock);
}void my_locks(void)
{
#ifdef DOWNLOAD_LOCKpthread_mutex_lock(&connlock);
#endif
} void my_unlocks(void)
{
#ifdef DOWNLOAD_LOCKpthread_mutex_unlock(&connlock);
#endif
}//lldebug LoginStr aftp:123456 RemoteFile: sftp://192.168.168.88/DataStorary/Server/MyData/BigFile.dat LocalFile: /tmp/data/download/BigFile.datstatic size_t my_write(void *buffer, size_t size, size_t nmemb, void *stream)
{/* not interested in the downloaded bytes, return the size */ (void)buffer; /* unused */ (void)stream; /* unused */ return (size_t)(size * nmemb);
}void downloadFile(CURL *curl, const char *LoginStr, const char * RemoteFile, const char *LocalFile)
{//CURL *curl = InitCurl();if(curl == NULL){return;}curl_easy_setopt(curl, CURLOPT_USERPWD, LoginStr);curl_easy_setopt(curl, CURLOPT_URL, RemoteFile);curl_easy_setopt(curl, CURLOPT_WRITEFUNCTION, my_write);printf("lldebug %s().%d before curl_easy_perform ptr: %p\n", __func__, __LINE__, curl);CURLcode code = curl_easy_perform(curl);if(CURLE_OK != code){printf("curl_easy_perform failed, %d: %s\n", code, curl_easy_strerror(code));}
}static void *download_1(void *url)
{CURL *curl;const char* loginStr = "aftp:123456";//const char* rfile = "sftp://192.168.168.88/DataStorary/Server/MyData/smallfile.txt";const char* rfile = "sftp://192.168.168.88/DataStorary/Server/MyData/BigFile.dat";const char* lfile = "/tmp/file_1.txt";my_locks();printf("lldebug %s().%d begin++++++++++++++++++\n", __func__, __LINE__);curl = curl_easy_init();printf("lldebug %s().%d >>>>>>>> init curl ptr: %p\n", __func__, __LINE__, curl);downloadFile(curl, loginStr, rfile, lfile);printf("lldebug %s().%d <<<<<<<< download done curl ptr: %p\n", __func__, __LINE__, curl);curl_easy_cleanup(curl);printf("lldebug %s().%d end++++++++++++++++++\n", __func__, __LINE__);my_unlocks();
}static void *download_2(void *url)
{CURL *curl;const char* loginStr = "aftp:123456";const char* rfile = "sftp://192.168.168.88/DataStorary/Server/MyData/smallfile.txt";const char* lfile = "/tmp/file_2.txt";my_locks();printf("lldebug %s().%d begin------------------\n", __func__, __LINE__);curl = curl_easy_init();printf("lldebug %s().%d >>>>>>>> init curl ptr: %p\n", __func__, __LINE__, curl);downloadFile(curl, loginStr, rfile, lfile);printf("lldebug %s().%d <<<<<<<< download done curl ptr: %p\n", __func__, __LINE__, curl);curl_easy_cleanup(curl);printf("lldebug %s().%d end------------------\n", __func__, __LINE__);my_unlocks();
}int main(int argc, char **argv)
{pthread_t tid1;pthread_t tid2;init_locks();curl_global_init(CURL_GLOBAL_ALL);pthread_create(&tid1, NULL, download_1, NULL);usleep(1000);pthread_create(&tid2, NULL, download_2, NULL);pthread_join(tid1, NULL);pthread_join(tid2, NULL);kill_locks();curl_global_cleanup();return 0;
}
编译:
g++ test_thread.cpp -I/usr/local/curl/include -I/usr/include -lcurl
加锁情况下运行结果:
lldebug download_1().78 begin++++++++++++++++++
lldebug download_1().82 >>>>>>>> init curl ptr: 0x9216340
lldebug downloadFile().57 before curl_easy_perform ptr: 0x9216340
lldebug download_1().86 <<<<<<<< download done curl ptr: 0x9216340
lldebug download_1().91 end++++++++++++++++++
lldebug download_2().105 begin------------------
lldebug download_2().110 >>>>>>>> init curl ptr: 0x9216340
lldebug downloadFile().57 before curl_easy_perform ptr: 0x9216340
lldebug download_2().114 <<<<<<<< download done curl ptr: 0x9216340
lldebug download_2().118 end------------------
不加锁情况下运行结果:
lldebug download_1().78 begin++++++++++++++++++
lldebug download_1().82 >>>>>>>> init curl ptr: 0x9d37340
lldebug downloadFile().57 before curl_easy_perform ptr: 0x9d37340
lldebug download_2().105 begin------------------
lldebug download_2().110 >>>>>>>> init curl ptr: 0x9d4de18
lldebug downloadFile().57 before curl_easy_perform ptr: 0x9d4de18
a.out: ath.c:193: _gcry_ath_mutex_lock: Assertion `*lock == ((ath_mutex_t) 0)' failed.
Aborted
用gdb调试过程:
(gdb) r
Starting program: /home/latelee/libcurl_test/a.out
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/i386-linux-gnu/i686/cmov/libthread_db.so.1".
[New Thread 0xb769eb70 (LWP 7680)]
lldebug download_1().101 begin++++++++++++++++++
lldebug download_1().105 >>>>>>>> init curl ptr: 0x805a340
lldebug downloadFile().80 before curl_easy_perform ptr: 0x805a340
[New Thread 0xb6e9db70 (LWP 7681)]
lldebug download_2().128 begin------------------
lldebug download_2().133 >>>>>>>> init curl ptr: 0x8070e18
lldebug downloadFile().80 before curl_easy_perform ptr: 0x8070e18
a.out: ath.c:193: _gcry_ath_mutex_lock: Assertion `*lock == ((ath_mutex_t) 0)' failed.Program received signal SIGABRT, Aborted.
[Switching to Thread 0xb6e9db70 (LWP 7681)]
0xb7fe1424 in __kernel_vsyscall ()
(gdb) bt
#0 0xb7fe1424 in __kernel_vsyscall ()
#1 0xb7cf5941 in *__GI_raise (sig=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
#2 0xb7cf8d72 in *__GI_abort () at abort.c:92
#3 0xb7ceeb58 in *__GI___assert_fail (assertion=0xb7938626 "*lock == ((ath_mutex_t) 0)", file=0xb7938620 "ath.c", line=193, function=0xb7938674 "_gcry_ath_mutex_lock") at assert.c:81
#4 0xb78e9605 in ?? () from /lib/i386-linux-gnu/libgcrypt.so.11
#5 0xb792b02d in ?? () from /lib/i386-linux-gnu/libgcrypt.so.11
#6 0xb792c889 in ?? () from /lib/i386-linux-gnu/libgcrypt.so.11
#7 0xb792ae7d in ?? () from /lib/i386-linux-gnu/libgcrypt.so.11
#8 0xb78f82d9 in ?? () from /lib/i386-linux-gnu/libgcrypt.so.11
#9 0xb78f8a14 in ?? () from /lib/i386-linux-gnu/libgcrypt.so.11
#10 0xb78e078c in gcry_md_open () from /lib/i386-linux-gnu/libgcrypt.so.11
#11 0xb7c603b6 in ?? () from /usr/lib/i386-linux-gnu/libssh2.so.1
#12 0xb7c6f154 in ?? () from /usr/lib/i386-linux-gnu/libssh2.so.1
#13 0xb7c5a2c8 in ?? () from /usr/lib/i386-linux-gnu/libssh2.so.1
#14 0xb7c67108 in ?? () from /usr/lib/i386-linux-gnu/libssh2.so.1
#15 0xb7c67489 in ?? () from /usr/lib/i386-linux-gnu/libssh2.so.1
#16 0xb7c680db in libssh2_sftp_init () from /usr/lib/i386-linux-gnu/libssh2.so.1
#17 0xb7fa0688 in ?? () from /usr/lib/i386-linux-gnu/libcurl.so.4
#18 0xb7fa3f63 in ?? () from /usr/lib/i386-linux-gnu/libcurl.so.4
#19 0xb7fa4595 in ?? () from /usr/lib/i386-linux-gnu/libcurl.so.4
#20 0xb7f80380 in ?? () from /usr/lib/i386-linux-gnu/libcurl.so.4
#21 0xb7f8067a in ?? () from /usr/lib/i386-linux-gnu/libcurl.so.4
#22 0xb7f80732 in ?? () from /usr/lib/i386-linux-gnu/libcurl.so.4
#23 0xb7f8d255 in ?? () from /usr/lib/i386-linux-gnu/libcurl.so.4
#24 0xb7f8e033 in curl_easy_perform () from /usr/lib/i386-linux-gnu/libcurl.so.4
#25 0x08048acf in downloadFile(void*, char const*, char const*, char const*) ()
#26 0x08048c60 in download_2(void*) ()
#27 0xb7cb7c39 in start_thread (arg=0xb6e9db70) at pthread_create.c:304
#28 0xb7da1d4e in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:130
(gdb)